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

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

Open
1 task done
takumi2786 opened this issue Dec 13, 2023 · 3 comments
Open
1 task done

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

takumi2786 opened this issue Dec 13, 2023 · 3 comments

Comments

@takumi2786
Copy link

takumi2786 commented Dec 13, 2023 •
edited

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.

  • Initially raised as discussion #...

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
Copy link
Author

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

@karpetrosyan
Copy link
Member

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

  • Have you tried using another HTTP client?
  • Have you tried trio instead of asyncio?
  • Have you tried different h2-based http2 implementations?
  • Have you tried reproducing this with just the httpcore package? (most likely you can)

@mborsetti
Copy link

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)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@mborsetti @takumi2786 @karpetrosyan