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.

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

x/net/http2: http.Server.WriteTimeout does not fire if the http2 stream's window is out of space. #49741

Open
davecheney opened this issue Nov 23, 2021 · 4 comments

Comments

@davecheney
Copy link
Contributor

@davecheney davecheney commented Nov 23, 2021

What version of Go are you using (go version)?

$ go version 1.17.3

Does this issue reproduce with the latest release?

yes

What operating system and processor architecture are you using (go env)?

What did you do?

package main

import (
	"io"
	"log"
	"net/http"
	"net/http/httptest"
	"strings"
	"time"
)

func handler(w http.ResponseWriter, r *http.Request) {
	data := strings.Repeat("x", 1<<16)
	tick := time.NewTicker(1 * time.Millisecond)
	defer tick.Stop()
	for {
		select {
		case <-tick.C:
			n, err := io.WriteString(w, data)
			log.Printf("wrote %d, err %v", n, err)
			if err != nil {
				return
			}
		case <-r.Context().Done():
			log.Printf("context cancelled")
			return
		}
	}
}

func main() {
	sv := httptest.NewUnstartedServer(http.HandlerFunc(handler))
	sv.EnableHTTP2 = true
	sv.Config.WriteTimeout = 1 * time.Second
	sv.StartTLS()

	resp, err := sv.Client().Get(sv.URL + "/")
	if err != nil {
		log.Fatal(err)
	}
	defer resp.Body.Close()

	select {} // block forever
}

This program creates a HTTP2 service which fills the HTTP/2 stream's response window by failing to consume any data from the response body. The write deadline should fire after 1 second and terminate the response. It does not.

What did you expect to see?

If the tick rate is increased to 100ms, the write timeout fires

(~/devel/http2bug) % go run .
2021/11/23 13:03:12 wrote 65536, err <nil>
2021/11/23 13:03:13 wrote 65536, err <nil>
2021/11/23 13:03:13 wrote 65536, err <nil>
2021/11/23 13:03:13 wrote 65536, err <nil>
2021/11/23 13:03:13 wrote 65536, err <nil>
2021/11/23 13:03:13 wrote 65536, err <nil>
2021/11/23 13:03:13 wrote 65536, err <nil>
2021/11/23 13:03:13 wrote 65536, err <nil>
2021/11/23 13:03:13 wrote 65536, err <nil>
2021/11/23 13:03:13 wrote 4096, err http2: stream closed

What did you see instead?

If tick is left at 1 ms, permitting it to fill the stream's response window, handler blocks, no timeout is reported on either the client or the server side.

(~/devel/http2bug) % go run .
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>
2021/11/23 13:03:56 wrote 65536, err <nil>

// output stops

/cc @neild @bradfitz

@aojea
Copy link

@aojea aojea commented Nov 24, 2021

If tick is left at 1 ms, permitting it to fill the stream's response window, handler blocks, no timeout is reported on either the client or the server side.

interestingly, you can increase the tick until 15ms, it always block when it writes 64 blocks. If I divide by 2 the data data := strings.Repeat("x", 1<<15) it blocks when it writes 128 blocks if I tick in less than 7 ms

It seems that something blocks when it has 64x65536 = 4MB, the bytes.Buffer?

const smallBufferSize = 64

Loading

@davecheney
Copy link
Contributor Author

@davecheney davecheney commented Nov 24, 2021

It seems that something blocks when it has 64x65536 = 4MB, the bytes.Buffer?

I believe that is the stream's window, as the client is not reading from the response stream it will not be triggering window updates to refill the window

Loading

@aojea
Copy link

@aojea aojea commented Nov 25, 2021

@davecheney you are right, I've found the problem, is the stream window as you say

I'll send a patch so you can review

Loading

@gopherbot
Copy link

@gopherbot gopherbot commented Nov 25, 2021

Change https://golang.org/cl/367154 mentions this issue: http2: RST_STREAM frames write priority

Loading

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Linked pull requests

Successfully merging a pull request may close this issue.

None yet
3 participants