search

encode / httpx

A next generation HTTP client for Python. 🦋
https://www.python-httpx.org/
BSD 3-Clause "New" or "Revised" License
13.35k stars 853 forks source link

httpx + http2 raises a lot of exceptions when parallelized with ThreadPoolExecuton #3002

Open takumi2786 opened 11 months ago

takumi2786 commented 11 months ago

The starting point for issues should usually be a discussion...

https://github.com/encode/httpx/discussions

Possible bugs may be raised as a "Potential Issue" discussion, feature requests may be raised as an "Ideas" discussion. We can then determine if the discussion needs to be escalated into an "Issue" or not.

This will help us ensure that the "Issues" list properly reflects ongoing or needed work on the project.

Problem

I tried to use httpx as http2 client and I want to execute multiple requests in parallel.

First, I tried to parallelize with ThreadPoolExecutor, but it threw a lot of exceptions. Then I used Asyncio and it worked.

reproducion

server

package main

import (
    "fmt"
    "log"
    "net/http"
    "time"

    "golang.org/x/net/http2"
)

func main() {
    http.HandleFunc("/", func(w http.ResponseWriter, r *http.Request) {
        time.Sleep(1 * time.Second)
        fmt.Println("Hello, HTTP/2!")
        fmt.Fprintf(w, "Hello, HTTP/2!")
    })

    server := &http.Server{
        Addr: ":8080",
    }

    http2.ConfigureServer(server, &http2.Server{})
    log.Fatal(server.ListenAndServeTLS("../server.crt", "../server.key"))
}

client

import asyncio
import httpx
from concurrent.futures import ThreadPoolExecutor, as_completed
from logging import basicConfig
basicConfig(level='DEBUG')

PARRALEL = 50

def request(client: httpx.Client):
    response = client.get(
        'https://localhost:8080/',
        timeout=httpx.Timeout(1.5),
    )
    print(response.http_version)
    print(response.text)
    return response

def batch_request():
    client = httpx.Client(
        http2=True,
        verify=False,
    )
    futures = []
    with ThreadPoolExecutor(max_workers=100) as executor:
        for i in range(PARRALEL):
            futures.append(executor.submit(request, client))    
    for future in as_completed(futures, timeout=5.0):
        result = future.result()
        print(result.http_version)
        print(result.text)

async def request_async(client: httpx.AsyncClient):
    response = await client.get(
        'https://localhost:8080/',
        timeout=httpx.Timeout(1.5),
    )
    print(response.http_version)
    print(response.text)
    return response

async def batch_request_async():
    async with httpx.AsyncClient(
        http2=True,
        verify=False,
    ) as client:
        tasks = []
        for i in range(PARRALEL):
            task = asyncio.create_task(request_async(client))
            tasks.append(task)

        for task in tasks:
            try:
                await task
            except Exception as e:
                print("exception!!!!", e)

def main_v2():
    loop = asyncio.get_event_loop()
    loop.run_until_complete(batch_request_async())

if __name__ == "__main__":
    # raise many error
    batch_request()

    # this works well
    # loop = asyncio.get_event_loop()
    # loop.run_until_complete(batch_request_async())
DEBUG:httpx:load_ssl_context verify=False cert=None trust_env=True http2=False
DEBUG:httpcore.connection:connect_tcp.started host='localhost' port=8080 local_address=None timeout=1.5 socket_options=None
DEBUG:httpcore.connection:connect_tcp.complete return_value=<httpcore._backends.sync.SyncStream object at 0x1034d2280>
DEBUG:httpcore.connection:start_tls.started ssl_context=<ssl.SSLContext object at 0x102feb4c0> server_hostname='localhost' timeout=1.5
DEBUG:httpcore.connection:start_tls.complete return_value=<httpcore._backends.sync.SyncStream object at 0x1034d21f0>
DEBUG:httpcore.http2:send_connection_init.started request=<Request [b'GET']>
DEBUG:httpcore.http2:send_connection_init.complete
DEBUG:httpcore.http2:send_request_headers.started request=<Request [b'GET']> stream_id=1
DEBUG:hpack.hpack:Adding (b':method', b'GET') to the header table, sensitive:False, huffman:True
DEBUG:hpack.hpack:Encoding 2 with 7 bits
DEBUG:hpack.hpack:Adding (b':authority', b'localhost:8080') to the header table, sensitive:False, huffman:True
DEBUG:hpack.hpack:Encoding 1 with 6 bits
DEBUG:hpack.hpack:Encoding 10 with 7 bits
DEBUG:hpack.hpack:Adding (b':scheme', b'https') to the header table, sensitive:False, huffman:True
DEBUG:hpack.hpack:Encoding 7 with 7 bits
DEBUG:hpack.hpack:Adding (b':path', b'/') to the header table, sensitive:False, huffman:True
DEBUG:hpack.hpack:Encoding 4 with 7 bits
DEBUG:hpack.hpack:Adding (b'accept', b'*/*') to the header table, sensitive:False, huffman:True
DEBUG:hpack.hpack:Encoding 19 with 6 bits
DEBUG:hpack.hpack:Encoding 3 with 7 bits
DEBUG:hpack.hpack:Adding (b'accept-encoding', b'gzip, deflate') to the header table, sensitive:False, huffman:True
DEBUG:hpack.hpack:Encoding 16 with 7 bits
DEBUG:hpack.hpack:Adding (b'user-agent', b'python-httpx/0.25.2') to the header table, sensitive:False, huffman:True
DEBUG:hpack.hpack:Encoding 58 with 6 bits
DEBUG:hpack.hpack:Encoding 14 with 7 bits
DEBUG:hpack.hpack:Encoded header block to b'\x82A\x8a\xa0\xe4\x1d\x13\x9d\t\xb8\xf0\x1e\x07\x87\x84S\x83\xf9c\xe7\x90z\x8e\xaf\xd2g=KN\x94\xd7\xe5\x80.&\xd7\x17'
DEBUG:httpcore.http2:send_request_headers.complete
DEBUG:httpcore.http2:send_request_body.started request=<Request [b'GET']> stream_id=1
DEBUG:httpcore.http2:send_request_body.complete
DEBUG:httpcore.http2:receive_response_headers.started request=<Request [b'GET']> stream_id=1
DEBUG:hpack.table:Resizing header table to 4096 from 4096
DEBUG:httpcore.http2:receive_remote_settings.started
DEBUG:httpcore.http2:receive_remote_settings.complete return_value=<RemoteSettingsChanged changed_settings:{ChangedSetting(setting=SettingCodes.MAX_FRAME_SIZE, original_value=16384, new_value=1048576), ChangedSetting(setting=SettingCodes.MAX_CONCURRENT_STREAMS, original_value=None, new_value=250), ChangedSetting(setting=SettingCodes.MAX_HEADER_LIST_SIZE, original_value=None, new_value=1048896), ChangedSetting(setting=SettingCodes.HEADER_TABLE_SIZE, original_value=4096, new_value=4096), ChangedSetting(setting=SettingCodes.INITIAL_WINDOW_SIZE, original_value=65535, new_value=1048576)}>
DEBUG:httpcore.http2:send_request_headers.started request=<Request [b'GET']> stream_id=3
DEBUG:hpack.hpack:Adding (b':method', b'GET') to the header table, sensitive:False, huffman:True
DEBUG:hpack.hpack:Encoding 2 with 7 bits
DEBUG:hpack.hpack:Adding (b':authority', b'localhost:8080') to the header table, sensitive:False, huffman:True
DEBUG:hpack.hpack:Encoding 64 with 7 bits
DEBUG:hpack.hpack:Adding (b':scheme', b'https') to the header table, sensitive:False, huffman:True
DEBUG:hpack.hpack:Encoding 7 with 7 bits
DEBUG:hpack.hpack:Adding (b':path', b'/') to the header table, sensitive:False, huffman:True
DEBUG:hpack.hpack:Encoding 4 with 7 bits
DEBUG:hpack.hpack:Adding (b'accept', b'*/*') to the header table, sensitive:False, huffman:True
DEBUG:httpcore.http2:send_request_headers.started request=<Request [b'GET']> stream_id=5
DEBUG:httpcore.http2:send_request_headers.started request=<Request [b'GET']> stream_id=5
DEBUG:httpcore.http2:send_request_headers.started request=<Request [b'GET']> stream_id=5
DEBUG:httpcore.http2:send_request_headers.started request=<Request [b'GET']> stream_id=5
DEBUG:httpcore.http2:send_request_headers.started request=<Request [b'GET']> stream_id=5
DEBUG:httpcore.http2:send_request_headers.started request=<Request [b'GET']> stream_id=5
DEBUG:httpcore.http2:send_request_headers.started request=<Request [b'GET']> stream_id=5
DEBUG:httpcore.http2:send_request_headers.started request=<Request [b'GET']> stream_id=5
DEBUG:httpcore.http2:send_request_headers.started request=<Request [b'GET']> stream_id=5
DEBUG:httpcore.http2:send_request_headers.started request=<Request [b'GET']> stream_id=5
DEBUG:httpcore.http2:send_request_headers.started request=<Request [b'GET']> stream_id=5
DEBUG:hpack.hpack:Encoding 63 with 7 bits
DEBUG:httpcore.http2:send_request_headers.started request=<Request [b'GET']> stream_id=5
DEBUG:hpack.hpack:Adding (b':method', b'GET') to the header table, sensitive:False, huffman:True
DEBUG:hpack.hpack:Adding (b':method', b'GET') to the header table, sensitive:False, huffman:True
DEBUG:httpcore.http2:send_request_headers.started request=<Request [b'GET']> stream_id=7
DEBUG:httpcore.http2:send_request_headers.failed exception=ProtocolError(AssertionError())
DEBUG:httpcore.http2:send_request_headers.started request=<Request [b'GET']> stream_id=7
DEBUG:httpcore.http2:send_request_headers.failed exception=StreamClosedError(5)
DEBUG:httpcore.http2:send_request_headers.started request=<Request [b'GET']> stream_id=7
DEBUG:httpcore.http2:send_request_headers.failed exception=StreamClosedError(5)
DEBUG:httpcore.http2:send_request_headers.started request=<Request [b'GET']> stream_id=7
DEBUG:httpcore.http2:send_request_headers.failed exception=StreamClosedError(5)
DEBUG:httpcore.http2:send_request_headers.started request=<Request [b'GET']> stream_id=7
DEBUG:httpcore.http2:send_request_headers.failed exception=StreamClosedError(5)
DEBUG:httpcore.http2:response_closed.started stream_id=5
DEBUG:httpcore.http2:send_request_headers.failed exception=StreamClosedError(5)
DEBUG:httpcore.http2:send_request_headers.failed exception=StreamClosedError(5)
DEBUG:httpcore.http2:send_request_headers.failed exception=StreamClosedError(5)
DEBUG:httpcore.http2:send_request_headers.started request=<Request [b'GET']> stream_id=7
DEBUG:httpcore.http2:send_request_headers.failed exception=StreamClosedError(5)
DEBUG:httpcore.http2:send_request_headers.started request=<Request [b'GET']> stream_id=7
DEBUG:hpack.hpack:Adding (b'accept-encoding', b'gzip, deflate') to the header table, sensitive:False, huffman:True
DEBUG:httpcore.http2:send_request_headers.started request=<Request [b'GET']> stream_id=7
DEBUG:httpcore.http2:send_request_headers.failed exception=StreamClosedError(5)
DEBUG:httpcore.http2:send_request_headers.started request=<Request [b'GET']> stream_id=7
DEBUG:hpack.hpack:Encoding 2 with 7 bits
DEBUG:httpcore.http2:send_request_headers.started request=<Request [b'GET']> stream_id=7
DEBUG:hpack.hpack:Encoding 2 with 7 bits
DEBUG:httpcore.http2:send_request_headers.started request=<Request [b'GET']> stream_id=7
DEBUG:hpack.hpack:Adding (b':method', b'GET') to the header table, sensitive:False, huffman:True
DEBUG:httpcore.http2:send_request_headers.started request=<Request [b'GET']> stream_id=9
DEBUG:httpcore.http2:response_closed.started stream_id=5
DEBUG:httpcore.http2:send_request_headers.started request=<Request [b'GET']> stream_id=9
DEBUG:hpack.hpack:Adding (b':method', b'GET') to the header table, sensitive:False, huffman:True
DEBUG:httpcore.http2:send_request_headers.started request=<Request [b'GET']> stream_id=9
DEBUG:httpcore.http2:response_closed.started stream_id=5
DEBUG:httpcore.http2:send_request_headers.started request=<Request [b'GET']> stream_id=9
DEBUG:httpcore.http2:send_request_headers.failed exception=ProtocolError(AssertionError())
DEBUG:httpcore.http2:send_request_headers.started request=<Request [b'GET']> stream_id=9
DEBUG:httpcore.http2:response_closed.started stream_id=5
DEBUG:httpcore.http2:send_request_headers.started request=<Request [b'GET']> stream_id=9
DEBUG:httpcore.http2:send_request_headers.started request=<Request [b'GET']> stream_id=9
DEBUG:httpcore.http2:send_request_headers.failed exception=StreamClosedError(7)
DEBUG:httpcore.http2:send_request_headers.started request=<Request [b'GET']> stream_id=9
DEBUG:httpcore.http2:response_closed.started stream_id=5
DEBUG:httpcore.http2:send_request_headers.started request=<Request [b'GET']> stream_id=9
DEBUG:httpcore.http2:send_request_headers.failed exception=StreamClosedError(7)
DEBUG:httpcore.http2:send_request_headers.started request=<Request [b'GET']> stream_id=9
DEBUG:httpcore.http2:send_request_headers.started request=<Request [b'GET']> stream_id=7
DEBUG:httpcore.http2:response_closed.complete
DEBUG:httpcore.http2:send_request_headers.started request=<Request [b'GET']> stream_id=9
DEBUG:httpcore.http2:send_request_headers.started request=<Request [b'GET']> stream_id=9
DEBUG:httpcore.http2:response_closed.started stream_id=5
DEBUG:httpcore.http2:send_request_headers.started request=<Request [b'GET']> stream_id=9
DEBUG:httpcore.http2:response_closed.started stream_id=5
DEBUG:httpcore.http2:send_request_headers.started request=<Request [b'GET']> stream_id=9
DEBUG:httpcore.http2:response_closed.started stream_id=5
DEBUG:httpcore.http2:send_request_headers.started request=<Request [b'GET']> stream_id=9
DEBUG:httpcore.http2:send_request_headers.failed exception=StreamClosedError(7)
DEBUG:httpcore.http2:send_request_headers.started request=<Request [b'GET']> stream_id=9
DEBUG:httpcore.http2:response_closed.started stream_id=5
DEBUG:httpcore.http2:send_request_headers.started request=<Request [b'GET']> stream_id=9
DEBUG:httpcore.http2:send_request_headers.started request=<Request [b'GET']> stream_id=9
DEBUG:httpcore.http2:send_request_headers.failed exception=StreamClosedError(7)
DEBUG:httpcore.http2:send_request_headers.started request=<Request [b'GET']> stream_id=9
DEBUG:hpack.hpack:Encoding 16 with 7 bits
DEBUG:httpcore.http2:send_request_headers.started request=<Request [b'GET']> stream_id=9
DEBUG:httpcore.http2:send_request_headers.failed exception=StreamClosedError(7)
DEBUG:httpcore.http2:send_request_headers.started request=<Request [b'GET']> stream_id=9
DEBUG:httpcore.http2:response_closed.started stream_id=5
DEBUG:httpcore.http2:send_request_headers.started request=<Request [b'GET']> stream_id=9
DEBUG:httpcore.http2:send_request_headers.failed exception=StreamClosedError(7)
DEBUG:httpcore.http2:send_request_headers.started request=<Request [b'GET']> stream_id=9
DEBUG:hpack.hpack:Adding (b':authority', b'localhost:8080') to the header table, sensitive:False, huffman:True
DEBUG:httpcore.http2:send_request_headers.started request=<Request [b'GET']> stream_id=9
DEBUG:httpcore.http2:send_request_headers.failed exception=StreamClosedError(7)
DEBUG:hpack.hpack:Adding (b':authority', b'localhost:8080') to the header table, sensitive:False, huffman:True
DEBUG:httpcore.http2:send_request_headers.failed exception=StreamClosedError(7)
DEBUG:hpack.hpack:Encoding 2 with 7 bits
DEBUG:hpack.hpack:Adding (b':method', b'GET') to the header table, sensitive:False, huffman:True
DEBUG:httpcore.http2:response_closed.failed exception=KeyError(5)
DEBUG:hpack.hpack:Adding (b':method', b'GET') to the header table, sensitive:False, huffman:True
DEBUG:hpack.hpack:Encoding 2 with 7 bits
DEBUG:httpcore.http2:send_request_headers.failed exception=ProtocolError(AssertionError())
DEBUG:httpcore.http2:response_closed.failed exception=KeyError(5)
DEBUG:httpcore.http2:send_request_headers.failed exception=StreamClosedError(9)
DEBUG:httpcore.http2:response_closed.started stream_id=7
DEBUG:httpcore.http2:send_request_headers.failed exception=StreamClosedError(9)
DEBUG:httpcore.http2:response_closed.failed exception=KeyError(5)
DEBUG:httpcore.http2:send_request_headers.failed exception=StreamClosedError(9)
DEBUG:httpcore.http2:send_request_headers.failed exception=StreamClosedError(9)
DEBUG:httpcore.http2:response_closed.started stream_id=7
DEBUG:httpcore.http2:send_request_headers.failed exception=StreamClosedError(9)
DEBUG:httpcore.http2:response_closed.failed exception=KeyError(5)
DEBUG:httpcore.http2:send_request_headers.failed exception=StreamClosedError(9)
DEBUG:httpcore.http2:response_closed.started stream_id=7
DEBUG:httpcore.http2:send_request_headers.failed exception=StreamClosedError(9)
DEBUG:httpcore.http2:send_request_headers.failed exception=StreamIDTooLowError(7, 9)
DEBUG:httpcore.http2:send_request_headers.failed exception=StreamIDTooLowError(9, 9)
DEBUG:httpcore.http2:send_request_headers.failed exception=StreamIDTooLowError(9, 9)
DEBUG:httpcore.http2:response_closed.failed exception=KeyError(5)
DEBUG:httpcore.http2:send_request_headers.failed exception=StreamIDTooLowError(9, 9)
DEBUG:httpcore.http2:response_closed.failed exception=KeyError(5)
DEBUG:httpcore.http2:send_request_headers.failed exception=StreamIDTooLowError(9, 9)
DEBUG:httpcore.http2:response_closed.failed exception=KeyError(5)
DEBUG:httpcore.http2:send_request_headers.failed exception=StreamIDTooLowError(9, 9)
DEBUG:httpcore.http2:response_closed.started stream_id=7
DEBUG:httpcore.http2:send_request_headers.failed exception=StreamIDTooLowError(9, 9)
DEBUG:httpcore.http2:response_closed.failed exception=KeyError(5)
DEBUG:httpcore.http2:send_request_headers.failed exception=StreamIDTooLowError(9, 9)
DEBUG:httpcore.http2:send_request_headers.failed exception=StreamIDTooLowError(9, 9)
DEBUG:httpcore.http2:response_closed.started stream_id=7
DEBUG:httpcore.http2:send_request_headers.failed exception=StreamIDTooLowError(9, 9)
DEBUG:hpack.hpack:Adding (b'user-agent', b'python-httpx/0.25.2') to the header table, sensitive:False, huffman:True
DEBUG:httpcore.http2:send_request_headers.failed exception=StreamIDTooLowError(9, 9)
DEBUG:httpcore.http2:response_closed.started stream_id=7
DEBUG:httpcore.http2:send_request_headers.failed exception=StreamIDTooLowError(9, 9)
DEBUG:httpcore.http2:response_closed.failed exception=KeyError(5)
DEBUG:httpcore.http2:send_request_headers.failed exception=StreamIDTooLowError(9, 9)
DEBUG:httpcore.http2:response_closed.started stream_id=7
DEBUG:httpcore.http2:send_request_headers.failed exception=StreamIDTooLowError(9, 9)
DEBUG:hpack.hpack:Encoding 64 with 7 bits
DEBUG:httpcore.http2:send_request_headers.failed exception=StreamIDTooLowError(9, 9)
DEBUG:httpcore.http2:response_closed.started stream_id=7
DEBUG:hpack.hpack:Encoding 64 with 7 bits
DEBUG:httpcore.http2:response_closed.started stream_id=7
DEBUG:hpack.hpack:Adding (b':authority', b'localhost:8080') to the header table, sensitive:False, huffman:True
DEBUG:hpack.hpack:Encoding 2 with 7 bits
DEBUG:hpack.hpack:Encoding 2 with 7 bits
DEBUG:hpack.hpack:Adding (b':authority', b'localhost:8080') to the header table, sensitive:False, huffman:True
DEBUG:httpcore.http2:response_closed.started stream_id=9
DEBUG:httpcore.http2:response_closed.started stream_id=9
DEBUG:httpcore.http2:response_closed.complete
DEBUG:httpcore.http2:response_closed.started stream_id=9
DEBUG:httpcore.http2:response_closed.started stream_id=9
DEBUG:httpcore.http2:response_closed.started stream_id=9
DEBUG:httpcore.http2:response_closed.failed exception=KeyError(7)
DEBUG:httpcore.http2:response_closed.started stream_id=9
DEBUG:httpcore.http2:response_closed.started stream_id=9
DEBUG:httpcore.http2:response_closed.failed exception=KeyError(7)
DEBUG:httpcore.http2:response_closed.started stream_id=9
DEBUG:httpcore.http2:response_closed.started stream_id=7
DEBUG:httpcore.http2:response_closed.started stream_id=9
DEBUG:httpcore.http2:response_closed.started stream_id=9
DEBUG:httpcore.http2:response_closed.started stream_id=9
DEBUG:httpcore.http2:response_closed.started stream_id=9
DEBUG:httpcore.http2:response_closed.started stream_id=9
DEBUG:httpcore.http2:response_closed.failed exception=KeyError(7)
DEBUG:httpcore.http2:response_closed.started stream_id=9
DEBUG:httpcore.http2:response_closed.started stream_id=9
DEBUG:httpcore.http2:response_closed.started stream_id=9
DEBUG:httpcore.http2:response_closed.failed exception=KeyError(7)
DEBUG:httpcore.http2:response_closed.started stream_id=9
DEBUG:hpack.hpack:Encoding 62 with 7 bits
DEBUG:httpcore.http2:response_closed.started stream_id=9
DEBUG:httpcore.http2:response_closed.failed exception=KeyError(7)
DEBUG:httpcore.http2:response_closed.started stream_id=9
DEBUG:httpcore.http2:response_closed.started stream_id=9
DEBUG:httpcore.http2:response_closed.failed exception=KeyError(7)
DEBUG:httpcore.http2:response_closed.started stream_id=9
DEBUG:hpack.hpack:Adding (b':scheme', b'https') to the header table, sensitive:False, huffman:True
DEBUG:httpcore.http2:response_closed.started stream_id=9
DEBUG:httpcore.http2:response_closed.failed exception=KeyError(7)
DEBUG:hpack.hpack:Adding (b':scheme', b'https') to the header table, sensitive:False, huffman:True
DEBUG:httpcore.http2:response_closed.failed exception=KeyError(7)
DEBUG:hpack.hpack:Encoding 64 with 7 bits
DEBUG:hpack.hpack:Adding (b':authority', b'localhost:8080') to the header table, sensitive:False, huffman:True
DEBUG:hpack.hpack:Adding (b':authority', b'localhost:8080') to the header table, sensitive:False, huffman:True
DEBUG:hpack.hpack:Encoding 64 with 7 bits
DEBUG:httpcore.http2:response_closed.complete
DEBUG:httpcore.http2:response_closed.failed exception=KeyError(9)
DEBUG:httpcore.http2:response_closed.failed exception=KeyError(9)
DEBUG:httpcore.http2:response_closed.failed exception=KeyError(9)
DEBUG:httpcore.http2:response_closed.failed exception=KeyError(9)
DEBUG:httpcore.http2:response_closed.failed exception=KeyError(9)
DEBUG:httpcore.http2:response_closed.failed exception=KeyError(9)
DEBUG:httpcore.http2:response_closed.failed exception=KeyError(9)
DEBUG:httpcore.http2:response_closed.failed exception=KeyError(7)
DEBUG:httpcore.http2:response_closed.failed exception=KeyError(9)
DEBUG:httpcore.http2:response_closed.failed exception=KeyError(9)
DEBUG:httpcore.http2:response_closed.failed exception=KeyError(9)
DEBUG:httpcore.http2:response_closed.failed exception=KeyError(9)
DEBUG:httpcore.http2:response_closed.failed exception=KeyError(9)
DEBUG:httpcore.http2:response_closed.failed exception=KeyError(9)
DEBUG:httpcore.http2:response_closed.failed exception=KeyError(9)
DEBUG:httpcore.http2:response_closed.failed exception=KeyError(9)
DEBUG:httpcore.http2:response_closed.failed exception=KeyError(9)
DEBUG:hpack.hpack:Encoded header block to b'\x82\xc0\x87\x84\xbf\x90\xbe'
DEBUG:httpcore.http2:response_closed.failed exception=KeyError(9)
DEBUG:httpcore.http2:response_closed.failed exception=KeyError(9)
DEBUG:httpcore.http2:response_closed.failed exception=KeyError(9)
DEBUG:httpcore.http2:response_closed.failed exception=KeyError(9)
DEBUG:hpack.hpack:Encoding 7 with 7 bits
DEBUG:httpcore.http2:response_closed.failed exception=KeyError(9)
DEBUG:hpack.hpack:Encoding 7 with 7 bits
DEBUG:hpack.hpack:Adding (b':scheme', b'https') to the header table, sensitive:False, huffman:True
DEBUG:hpack.hpack:Encoding 64 with 7 bits
DEBUG:hpack.hpack:Encoding 64 with 7 bits
DEBUG:hpack.hpack:Adding (b':scheme', b'https') to the header table, sensitive:False, huffman:True
DEBUG:httpcore.http2:send_request_headers.complete
DEBUG:hpack.hpack:Adding (b':path', b'/') to the header table, sensitive:False, huffman:True
DEBUG:hpack.hpack:Adding (b':path', b'/') to the header table, sensitive:False, huffman:True
DEBUG:hpack.hpack:Encoding 7 with 7 bits
DEBUG:hpack.hpack:Adding (b':scheme', b'https') to the header table, sensitive:False, huffman:True
DEBUG:hpack.hpack:Adding (b':scheme', b'https') to the header table, sensitive:False, huffman:True
DEBUG:hpack.hpack:Encoding 7 with 7 bits
DEBUG:httpcore.http2:send_request_body.started request=<Request [b'GET']> stream_id=3
DEBUG:hpack.hpack:Encoding 4 with 7 bits
DEBUG:hpack.hpack:Encoding 4 with 7 bits
DEBUG:hpack.hpack:Adding (b':path', b'/') to the header table, sensitive:False, huffman:True
DEBUG:hpack.hpack:Encoding 7 with 7 bits
DEBUG:hpack.hpack:Encoding 7 with 7 bits
DEBUG:hpack.hpack:Adding (b':path', b'/') to the header table, sensitive:False, huffman:True
DEBUG:httpcore.http2:send_request_body.complete
DEBUG:hpack.hpack:Adding (b'accept', b'*/*') to the header table, sensitive:False, huffman:True
DEBUG:hpack.hpack:Adding (b'accept', b'*/*') to the header table, sensitive:False, huffman:True
DEBUG:hpack.hpack:Encoding 4 with 7 bits
DEBUG:hpack.hpack:Adding (b':path', b'/') to the header table, sensitive:False, huffman:True
DEBUG:hpack.hpack:Adding (b':path', b'/') to the header table, sensitive:False, huffman:True
DEBUG:hpack.hpack:Encoding 4 with 7 bits
DEBUG:httpcore.http2:receive_response_headers.started request=<Request [b'GET']> stream_id=3
DEBUG:hpack.hpack:Encoding 63 with 7 bits
DEBUG:hpack.hpack:Encoding 63 with 7 bits
DEBUG:hpack.hpack:Adding (b'accept', b'*/*') to the header table, sensitive:False, huffman:True
DEBUG:hpack.hpack:Encoding 4 with 7 bits
DEBUG:hpack.hpack:Encoding 4 with 7 bits
DEBUG:hpack.hpack:Adding (b'accept', b'*/*') to the header table, sensitive:False, huffman:True
DEBUG:hpack.hpack:Adding (b'accept-encoding', b'gzip, deflate') to the header table, sensitive:False, huffman:True
DEBUG:hpack.hpack:Adding (b'accept-encoding', b'gzip, deflate') to the header table, sensitive:False, huffman:True
DEBUG:hpack.hpack:Encoding 63 with 7 bits
DEBUG:hpack.hpack:Adding (b'accept', b'*/*') to the header table, sensitive:False, huffman:True
DEBUG:hpack.hpack:Adding (b'accept', b'*/*') to the header table, sensitive:False, huffman:True
DEBUG:hpack.hpack:Encoding 63 with 7 bits
DEBUG:hpack.hpack:Encoding 16 with 7 bits
DEBUG:hpack.hpack:Encoding 16 with 7 bits
DEBUG:hpack.hpack:Adding (b'accept-encoding', b'gzip, deflate') to the header table, sensitive:False, huffman:True
DEBUG:hpack.hpack:Encoding 63 with 7 bits
DEBUG:hpack.hpack:Encoding 63 with 7 bits
DEBUG:hpack.hpack:Adding (b'accept-encoding', b'gzip, deflate') to the header table, sensitive:False, huffman:True
DEBUG:hpack.hpack:Adding (b'user-agent', b'python-httpx/0.25.2') to the header table, sensitive:False, huffman:True
DEBUG:hpack.hpack:Adding (b'user-agent', b'python-httpx/0.25.2') to the header table, sensitive:False, huffman:True
DEBUG:hpack.hpack:Encoding 62 with 7 bits
DEBUG:hpack.hpack:Adding (b'accept-encoding', b'gzip, deflate') to the header table, sensitive:False, huffman:True
DEBUG:hpack.hpack:Adding (b'accept-encoding', b'gzip, deflate') to the header table, sensitive:False, huffman:True
DEBUG:hpack.hpack:Encoding 16 with 7 bits
DEBUG:hpack.hpack:Encoding 62 with 7 bits
DEBUG:httpcore.http2:send_request_headers.failed exception=ProtocolError("Received pseudo-header in trailer {b':path', b':method', b':authority', b':scheme'}")
DEBUG:hpack.hpack:Encoding 16 with 7 bits
DEBUG:hpack.hpack:Encoding 16 with 7 bits
DEBUG:hpack.hpack:Encoding 16 with 7 bits
DEBUG:hpack.hpack:Adding (b'user-agent', b'python-httpx/0.25.2') to the header table, sensitive:False, huffman:True
DEBUG:hpack.hpack:Encoded header block to b'\x82\xc0\x87\x84\xbf\x90\xbe'
DEBUG:httpcore.http2:response_closed.started stream_id=5
DEBUG:hpack.hpack:Adding (b'user-agent', b'python-httpx/0.25.2') to the header table, sensitive:False, huffman:True
DEBUG:hpack.hpack:Adding (b'user-agent', b'python-httpx/0.25.2') to the header table, sensitive:False, huffman:True
DEBUG:hpack.hpack:Adding (b'user-agent', b'python-httpx/0.25.2') to the header table, sensitive:False, huffman:True
DEBUG:hpack.hpack:Encoding 62 with 7 bits
DEBUG:httpcore.http2:send_request_headers.failed exception=StreamClosedError(5)
DEBUG:httpcore.http2:response_closed.failed exception=KeyError(5)
DEBUG:hpack.hpack:Encoding 62 with 7 bits
DEBUG:hpack.hpack:Encoding 62 with 7 bits
DEBUG:hpack.hpack:Encoding 62 with 7 bits
DEBUG:httpcore.http2:send_request_headers.failed exception=ProtocolError("Received pseudo-header in trailer {b':path', b':method', b':authority', b':scheme'}")
DEBUG:httpcore.http2:response_closed.started stream_id=5
DEBUG:hpack.hpack:Encoded header block to b'\x82\xc0\x87\x84\xbf\x90\xbe'
DEBUG:hpack.hpack:Encoded header block to b'\x82\xc0\x87\x84\xbf\x90\xbe'
DEBUG:httpcore.http2:send_request_headers.failed exception=ProtocolError("Received pseudo-header in trailer {b':path', b':method', b':authority', b':scheme'}")
DEBUG:httpcore.http2:response_closed.started stream_id=9
DEBUG:httpcore.http2:response_closed.failed exception=KeyError(5)
DEBUG:httpcore.http2:send_request_headers.failed exception=StreamClosedError(7)
DEBUG:httpcore.http2:send_request_headers.failed exception=StreamClosedError(9)
DEBUG:httpcore.http2:response_closed.started stream_id=7
DEBUG:httpcore.http2:response_closed.failed exception=KeyError(9)
DEBUG:httpcore.http2:response_closed.started stream_id=7
DEBUG:httpcore.http2:response_closed.started stream_id=9
DEBUG:httpcore.http2:response_closed.failed exception=KeyError(7)
DEBUG:httpcore.http2:response_closed.failed exception=KeyError(7)
DEBUG:httpcore.http2:response_closed.failed exception=KeyError(9)
DEBUG:hpack.hpack:Decoding b'?\xe1\x1f\x88_\x92I|\xa5\x8a\xe8\x19\xaa\xfbP\x93\x8e\xc4\x150Z\x99V{\\\x0214a\x96\xe4Y>\x94\x0b*_)\x14\x10\x04\xca\x80~\xe0\x85pO)\x8bF\xff'
DEBUG:hpack.hpack:Decoded 4096, consumed 3 bytes
DEBUG:hpack.table:Resizing header table to 4096 from 4096
DEBUG:hpack.hpack:Decoded 8, consumed 1 bytes
DEBUG:hpack.hpack:Decoded (b':status', b'200'), consumed 1
DEBUG:hpack.hpack:Decoded 31, consumed 1 bytes
DEBUG:hpack.hpack:Decoded 18, consumed 1 bytes
DEBUG:hpack.hpack:Decoded (b'content-type', b'text/plain; charset=utf-8'), total consumed 20 bytes, indexed True
DEBUG:hpack.hpack:Decoded 28, consumed 1 bytes
DEBUG:hpack.hpack:Decoded 2, consumed 1 bytes
DEBUG:hpack.hpack:Decoded (b'content-length', <memory at 0x1033d5e80>), total consumed 4 bytes, indexed True
DEBUG:hpack.hpack:Decoded 33, consumed 1 bytes
DEBUG:hpack.hpack:Decoded 22, consumed 1 bytes
DEBUG:hpack.hpack:Decoded (b'date', b'Wed, 13 Dec 2023 09:22:28 GMT'), total consumed 24 bytes, indexed True
DEBUG:httpcore.http2:receive_response_headers.complete return_value=(200, [(b'content-type', b'text/plain; charset=utf-8'), (b'content-length', b'14'), (b'date', b'Wed, 13 Dec 2023 09:22:28 GMT')])
INFO:httpx:HTTP Request: GET https://localhost:8080/ "HTTP/2 200 OK"
DEBUG:httpcore.http2:receive_response_body.started request=<Request [b'GET']> stream_id=1
DEBUG:httpcore.http2:receive_response_body.complete
DEBUG:httpcore.http2:response_closed.started stream_id=1
DEBUG:httpcore.http2:response_closed.complete
DEBUG:hpack.hpack:Decoding b'\x88\xc0\xbf\xbe'
DEBUG:hpack.hpack:Decoded 8, consumed 1 bytes
DEBUG:hpack.hpack:Decoded (b':status', b'200'), consumed 1
DEBUG:hpack.hpack:Decoded 64, consumed 1 bytes
DEBUG:hpack.hpack:Decoded (b'content-type', b'text/plain; charset=utf-8'), consumed 1
DEBUG:hpack.hpack:Decoded 63, consumed 1 bytes
DEBUG:hpack.hpack:Decoded (b'content-length', <memory at 0x1033d5e80>), consumed 1
DEBUG:hpack.hpack:Decoded 62, consumed 1 bytes
DEBUG:hpack.hpack:Decoded (b'date', b'Wed, 13 Dec 2023 09:22:28 GMT'), consumed 1
DEBUG:httpcore.http2:receive_response_headers.complete return_value=(200, [(b'content-type', b'text/plain; charset=utf-8'), (b'content-length', b'14'), (b'date', b'Wed, 13 Dec 2023 09:22:28 GMT')])
INFO:httpx:HTTP Request: GET https://localhost:8080/ "HTTP/2 200 OK"
DEBUG:httpcore.http2:receive_response_body.started request=<Request [b'GET']> stream_id=3
DEBUG:httpcore.http2:receive_response_body.complete
DEBUG:httpcore.http2:response_closed.started stream_id=3
DEBUG:httpcore.http2:response_closed.complete
Traceback (most recent call last):
  File "/Users/t-ibayashi/Workspace/hackscripts/dev/http2/.venv/lib/python3.8/site-packages/httpcore/_sync/http2.py", line 142, in handle_request
    self._send_request_headers(request=request, stream_id=stream_id)
  File "/Users/t-ibayashi/Workspace/hackscripts/dev/http2/.venv/lib/python3.8/site-packages/httpcore/_sync/http2.py", line 247, in _send_request_headers
    self._h2_state.send_headers(stream_id, headers, end_stream=end_stream)
  File "/Users/t-ibayashi/Workspace/hackscripts/dev/http2/.venv/lib/python3.8/site-packages/h2/connection.py", line 770, in send_headers
    frames = stream.send_headers(
  File "/Users/t-ibayashi/Workspace/hackscripts/dev/http2/.venv/lib/python3.8/site-packages/h2/stream.py", line 863, in send_headers
    events = self.state_machine.process_input(input_)
  File "/Users/t-ibayashi/Workspace/hackscripts/dev/http2/.venv/lib/python3.8/site-packages/h2/stream.py", line 129, in process_input
    return func(self, previous_state)
  File "/Users/t-ibayashi/Workspace/hackscripts/dev/http2/.venv/lib/python3.8/site-packages/h2/stream.py", line 350, in send_on_closed_stream
    raise StreamClosedError(self.stream_id)
h2.exceptions.StreamClosedError: 7

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "client.py", line 69, in <module>
    batch_request()
  File "client.py", line 31, in batch_request
    result = future.result()
  File "/Users/t-ibayashi/.pyenv/versions/3.8.16/lib/python3.8/concurrent/futures/_base.py", line 437, in result
    return self.__get_result()
  File "/Users/t-ibayashi/.pyenv/versions/3.8.16/lib/python3.8/concurrent/futures/_base.py", line 389, in __get_result
    raise self._exception
  File "/Users/t-ibayashi/.pyenv/versions/3.8.16/lib/python3.8/concurrent/futures/thread.py", line 57, in run
    result = self.fn(*self.args, **self.kwargs)
  File "client.py", line 12, in request
    response = client.get(
  File "/Users/t-ibayashi/Workspace/hackscripts/dev/http2/.venv/lib/python3.8/site-packages/httpx/_client.py", line 1041, in get
    return self.request(
  File "/Users/t-ibayashi/Workspace/hackscripts/dev/http2/.venv/lib/python3.8/site-packages/httpx/_client.py", line 814, in request
    return self.send(request, auth=auth, follow_redirects=follow_redirects)
  File "/Users/t-ibayashi/Workspace/hackscripts/dev/http2/.venv/lib/python3.8/site-packages/httpx/_client.py", line 901, in send
    response = self._send_handling_auth(
  File "/Users/t-ibayashi/Workspace/hackscripts/dev/http2/.venv/lib/python3.8/site-packages/httpx/_client.py", line 929, in _send_handling_auth
    response = self._send_handling_redirects(
  File "/Users/t-ibayashi/Workspace/hackscripts/dev/http2/.venv/lib/python3.8/site-packages/httpx/_client.py", line 966, in _send_handling_redirects
    response = self._send_single_request(request)
  File "/Users/t-ibayashi/Workspace/hackscripts/dev/http2/.venv/lib/python3.8/site-packages/httpx/_client.py", line 1002, in _send_single_request
    response = transport.handle_request(request)
  File "/Users/t-ibayashi/Workspace/hackscripts/dev/http2/.venv/lib/python3.8/site-packages/httpx/_transports/default.py", line 228, in handle_request
    resp = self._pool.handle_request(req)
  File "/Users/t-ibayashi/Workspace/hackscripts/dev/http2/.venv/lib/python3.8/site-packages/httpcore/_sync/connection_pool.py", line 268, in handle_request
    raise exc
  File "/Users/t-ibayashi/Workspace/hackscripts/dev/http2/.venv/lib/python3.8/site-packages/httpcore/_sync/connection_pool.py", line 251, in handle_request
    response = connection.handle_request(request)
  File "/Users/t-ibayashi/Workspace/hackscripts/dev/http2/.venv/lib/python3.8/site-packages/httpcore/_sync/connection.py", line 103, in handle_request
    return self._connection.handle_request(request)
  File "/Users/t-ibayashi/Workspace/hackscripts/dev/http2/.venv/lib/python3.8/site-packages/httpcore/_sync/http2.py", line 167, in handle_request
    self._response_closed(stream_id=stream_id)
  File "/Users/t-ibayashi/Workspace/hackscripts/dev/http2/.venv/lib/python3.8/site-packages/httpcore/_sync/http2.py", line 406, in _response_closed
    del self._events[stream_id]
KeyError: 7
takumi2786 commented 11 months ago

I noticed something strange, this only seems to happen when the log level is set to DEBUG.

karpetrosyan commented 11 months ago

Here are some questions to help us figure out where the issue is:

mborsetti commented 9 months ago

Yeah, it's a pain. My workaround (solution) was to add this code whenever I run with DEBUG:

logging.getLogger('httpcore').setLevel(logging.INFO)
logging.getLogger('hpack').setLevel(logging.INFO)