[http2] Fast requests' results are not being returned to the caller until the slow ones on the same connection finish

[alekseyl1992]

Real setting:
we need to send a lot of long-polling requests with different parameters to the same server
thankfully this server supports http/2, so we don't need to initiate a lot of tcp-connection and can use http2-streams

The problem:
Slow requests "pause" handling of the fast ones.

To reproduce the issue in a controlled environment, I have created a test server (in golang). This server sleeps upon receiving each request for 1 or 10 seconds depending in the ?fast=1 parameter in the url query (it doesn't block other requests, the sleep is non-blocking operation). This makes it possible to see the interference between to kinds of requests: slow and fast ones, simulating the real long-polling situation.

The server code

package main

import (
	"fmt"
	"golang.org/x/net/http2"
	"golang.org/x/net/http2/h2c"
	"time"
)

import (
	"net/http"
)


func main() {
	h2s := &http2.Server{}

	handler := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		fast := false
		if r.URL.Query().Get("fast") == "1" {
			fast = true
			time.Sleep(1 * time.Second)
		} else {
			time.Sleep(10 * time.Second)
		}

		res := fmt.Sprintf("Hello, %v, http: %v, fast: %v\n", r.URL.Path, r.Proto, fast)
		fmt.Printf(res)
		fmt.Fprintf(w, res)
	})

	server := &http.Server{
		Addr:    "0.0.0.0:1010",
		Handler: h2c.NewHandler(handler, h2s),
	}

	fmt.Printf("Listening [0.0.0.0:1010]...\n")
	err := server.ListenAndServe()
	if err != nil {
		fmt.Printf("%v", err)
	}
}

And I've written two test clients: one in python (using httpx) and one in golang.
Python client code

import asyncio
import logging

import httpx
from httpx import Timeout


async def main():
    logging.basicConfig(level=logging.INFO, format='%(asctime)-15s %(message)s')
    logging.info('Henlo')

    limits = httpx.Limits(max_keepalive_connections=20, max_connections=21)

    async with httpx.AsyncClient(
            limits=limits,
            http1=False,
            http2=True,
            timeout=Timeout(
                read=5000,
                write=5000,
                connect=5000,
                pool=5000,
            )
    ) as client:
        t1 = asyncio.create_task(
            t(client, 'http://localhost:1010?fast=1'))
        t2 = asyncio.create_task(
            t(client, 'http://localhost:1010'))

        await asyncio.gather(t1, t2)


async def t(client: httpx.AsyncClient, url):
    while True:
        resp = await client.get(url)
        logging.info('%s %s %s', url, resp.text, resp.http_version)


if __name__ == '__main__':
    asyncio.run(main())

Now let's run the server and the Python client and see the client's output:

2021-07-21 22:06:42,243 Henlo
2021-07-21 22:06:43,335 http://localhost:1010?fast=1 Hello, /, http: HTTP/2.0, fast: true
 HTTP/2
2021-07-21 22:06:44,345 http://localhost:1010?fast=1 Hello, /, http: HTTP/2.0, fast: true
 HTTP/2
2021-07-21 22:06:45,348 http://localhost:1010?fast=1 Hello, /, http: HTTP/2.0, fast: true
 HTTP/2
2021-07-21 22:06:46,351 http://localhost:1010?fast=1 Hello, /, http: HTTP/2.0, fast: true
 HTTP/2
2021-07-21 22:06:47,355 http://localhost:1010?fast=1 Hello, /, http: HTTP/2.0, fast: true
 HTTP/2
2021-07-21 22:06:48,359 http://localhost:1010?fast=1 Hello, /, http: HTTP/2.0, fast: true
 HTTP/2
2021-07-21 22:06:49,362 http://localhost:1010?fast=1 Hello, /, http: HTTP/2.0, fast: true
 HTTP/2
2021-07-21 22:06:50,374 http://localhost:1010?fast=1 Hello, /, http: HTTP/2.0, fast: true
 HTTP/2
2021-07-21 22:06:51,377 http://localhost:1010?fast=1 Hello, /, http: HTTP/2.0, fast: true
 HTTP/2
2021-07-21 22:06:52,345 http://localhost:1010 Hello, /, http: HTTP/2.0, fast: false
 HTTP/2
2021-07-21 22:06:52,391 http://localhost:1010?fast=1 Hello, /, http: HTTP/2.0, fast: true
 HTTP/2
2021-07-21 22:07:02,350 http://localhost:1010?fast=1 Hello, /, http: HTTP/2.0, fast: true
 HTTP/2
2021-07-21 22:07:03,361 http://localhost:1010 Hello, /, http: HTTP/2.0, fast: false
 HTTP/2
2021-07-21 22:07:13,365 http://localhost:1010?fast=1 Hello, /, http: HTTP/2.0, fast: true
 HTTP/2
2021-07-21 22:07:14,382 http://localhost:1010 Hello, /, http: HTTP/2.0, fast: false
 HTTP/2

As you can see, I've recieved 9 "fast" responses with 1 seconds interval each, than 1 slow one after 10 seconds interval - that's all expected.
But after that "fast" requests are being responded each 10 seconds. Why?

From the real setting I know that "fast" requests' responses are being consumed by the caller code only when the slow one finishes.

It seems like there is some kind of connection locking issue inside of httpcore library which blocks the whole connection waiting for the data on one (in that case slow) stream.

To make sure that there is not issue with the server code, I've written another test client - in golang.
Golang client code

package main

import (
	"crypto/tls"
	"fmt"
	"golang.org/x/net/http2"
	"io/ioutil"
	"log"
	"net"
	"net/http"
	"time"
)

func main() {
	client := &http.Client{
		Transport: &http2.Transport{
			AllowHTTP: true,
			DialTLS: func(network, addr string, cfg *tls.Config) (net.Conn, error) {
				return net.Dial(network, addr)
			},
		},
	}

	go t(client, "http://localhost:1010?fast=1")
	go t(client, "http://localhost:1010")

	select{}
}

func t(client *http.Client, url string) {
	for {
		resp, err := client.Get(url)
		if err != nil {
			log.Fatalf("Failed get: %s", err)
		}
		body, err := ioutil.ReadAll(resp.Body)
		if err != nil {
			log.Fatalf("Failed reading response body: %s", err)
		}
		err = resp.Body.Close()
		if err != nil {
			log.Fatalf("Failed closing response body: %s", err)
		}

		fmt.Printf(
			"%v %s\n",
			time.Now().Format(time.RFC3339), string(body))
	}
}

And the output is perfectly fine:

2021-07-21T22:21:58+03:00 Hello, /, http: HTTP/2.0, fast: true

2021-07-21T22:21:59+03:00 Hello, /, http: HTTP/2.0, fast: true

2021-07-21T22:22:00+03:00 Hello, /, http: HTTP/2.0, fast: true

2021-07-21T22:22:01+03:00 Hello, /, http: HTTP/2.0, fast: true

2021-07-21T22:22:02+03:00 Hello, /, http: HTTP/2.0, fast: true

2021-07-21T22:22:03+03:00 Hello, /, http: HTTP/2.0, fast: true

2021-07-21T22:22:04+03:00 Hello, /, http: HTTP/2.0, fast: true

2021-07-21T22:22:05+03:00 Hello, /, http: HTTP/2.0, fast: true

2021-07-21T22:22:06+03:00 Hello, /, http: HTTP/2.0, fast: true

2021-07-21T22:22:07+03:00 Hello, /, http: HTTP/2.0, fast: false

2021-07-21T22:22:07+03:00 Hello, /, http: HTTP/2.0, fast: true

2021-07-21T22:22:08+03:00 Hello, /, http: HTTP/2.0, fast: true

2021-07-21T22:22:09+03:00 Hello, /, http: HTTP/2.0, fast: true

2021-07-21T22:22:10+03:00 Hello, /, http: HTTP/2.0, fast: true

2021-07-21T22:22:11+03:00 Hello, /, http: HTTP/2.0, fast: true

2021-07-21T22:22:12+03:00 Hello, /, http: HTTP/2.0, fast: true

2021-07-21T22:22:13+03:00 Hello, /, http: HTTP/2.0, fast: true

2021-07-21T22:22:14+03:00 Hello, /, http: HTTP/2.0, fast: true

2021-07-21T22:22:15+03:00 Hello, /, http: HTTP/2.0, fast: true

2021-07-21T22:22:16+03:00 Hello, /, http: HTTP/2.0, fast: true

2021-07-21T22:22:17+03:00 Hello, /, http: HTTP/2.0, fast: false

2021-07-21T22:22:17+03:00 Hello, /, http: HTTP/2.0, fast: true

2021-07-21T22:22:18+03:00 Hello, /, http: HTTP/2.0, fast: true

2021-07-21T22:22:19+03:00 Hello, /, http: HTTP/2.0, fast: true

2021-07-21T22:22:20+03:00 Hello, /, http: HTTP/2.0, fast: true

2021-07-21T22:22:21+03:00 Hello, /, http: HTTP/2.0, fast: true

Each fast request being responded once per second.
The slow ones being responded once per 10 seconds.

Apparently httpx/httpcore blocks fast responses waiting for the other (slow) requests to finish. And golang client doesn't have this problem: all the streams are being handled independently.

I've tried removing read_lock in the httpcore's http2 implementation, but it didn't help :(

Versions
Python 3.8.1
httpx[http2]==0.18.2
go1.13.4