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

net/http: remote end of long POST request randomly closes when using http2 #65426

Open
ghost opened this issue Feb 1, 2024 · 2 comments
Open

net/http: remote end of long POST request randomly closes when using http2 #65426

ghost opened this issue Feb 1, 2024 · 2 comments
Labels
NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone
Backlog

Comments

@ghost
Copy link

ghost commented Feb 1, 2024

Go version

go1.20.5

Output of go env in your module/workspace:

GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/root/.cache/go-build"
GOENV="/root/.config/go/env"
GOEXE=""
GOEXPERIMENT=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GOMODCACHE="/root/go/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/root/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/local/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go/pkg/tool/linux_amd64"
GOVCS=""
GOVERSION="go1.20.5"
GCCGO="gccgo"
GOAMD64="v1"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD="/dev/null"
GOWORK=""
CGO_CFLAGS="-O2 -g"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-O2 -g"
CGO_FFLAGS="-O2 -g"
CGO_LDFLAGS="-O2 -g"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -Wl,--no-gc-sections -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build1695464211=/tmp/go-build -gno-record-gcc-switches"

What did you do?

I have two applications where the client application makes a HTTP/2 POST request to a server application.

The request is kept open permanently, effectively creating a bidirectional socket. In our case the client application continuously reads JSONL from the response body.

The server application receives the request and occasionally (just a couple times per day) writes some JSONL to the response body.

Equivalent code for the client application:

func main() {
	client := &http.Client{ /* HTTP2 transport */ }
	reader, writer := io.Pipe()
	encoder := json.NewEncoder(writer)
	go func() {
		encoder.Encode(/* some data */)
		// more data may be sent in the future so writer is never closed
	}()
	response, err := this.client.Post(url, content_type, reader)
	defer response.Body.Close()
	decoder := json.NewDecoder(response.Body)
	for {
		var msg map[string]any
		decoder.Decode(&msg)
	}
}

Equivalent code for the server application:

func main() {
	server := &http.Server{Addr: ":12345"}
	http.HandleFunc("/", func(w http.ResponseWriter, r *http.Request) {
		decoder := json.NewDecoder(r.Body)
		go func() {
			encoder := json.NewEncoder(w)
			for {
				time.Sleep(time.Hour * 10)
				encoder.Encode(/* some data */)
				w.(http.Flusher).Flush()
			}
		}()
		defer log.Println("Client disconnected") // never happens
		// likely because request body is never terminated
		for {
			var msg map[string]any
			decoder.Decode(&msg)
		}
	})
	server.ListenAndServeTLS(certificate, keyfile)
}

What did you see happen?

The two applications are able to communicate fine for hours/days/weeks but every now and then the response body becomes closed on the server for unknown reasons, resulting in short write errors.

I've tried to debug the issue by logging reads with io.TeeReader and writes with io.MultiWriter. The logs show that writes are attempted. JSONL is in fact sent over the wire as confirmed with tcpdump (even with SSL encryption, large blobs of data are easy to spot) despite short write errors. My guess is that only part of the JSONL is written, explaining the errors I am seeing.

However, none of the bytes appearing on the wire are read by the client, nothing shows up in the log and reads never return EOF. This means the client will patiently wait forever, oblivious of the fact that something is wrong.

Is there some built-in timeout I'm not aware of?

What did you expect to see?

For the applications to continue talking to each other.
@ghost
Copy link
Author

ghost commented Feb 1, 2024

Added GODEBUG=http2debug=1

Seeing thousands of window updates per second. Is that normal?

Feb 01 14:03:04 [2701602]: http2: server read frame WINDOW_UPDATE stream=39 len=4 incr=16384
Feb 01 14:03:04 [2701602]: http2: server read frame WINDOW_UPDATE len=4 (conn) incr=16384
Feb 01 14:03:04 [2701602]: http2: server read frame WINDOW_UPDATE stream=41 len=4 incr=16384
Feb 01 14:03:04 [2701602]: http2: server read frame WINDOW_UPDATE len=4 (conn) incr=16384
Feb 01 14:03:04 [2701602]: http2: server read frame WINDOW_UPDATE stream=41 len=4 incr=16384
Feb 01 14:03:04 [2701602]: http2: server read frame WINDOW_UPDATE len=4 (conn) incr=16384
Feb 01 14:03:04 [2701602]: http2: server read frame WINDOW_UPDATE stream=39 len=4 incr=16384
Feb 01 14:03:04 [2701602]: http2: server read frame WINDOW_UPDATE len=4 (conn) incr=16384
Feb 01 14:03:04 [2701602]: http2: server read frame WINDOW_UPDATE stream=39 len=4 incr=16384
Feb 01 14:03:04 [2701602]: http2: server read frame WINDOW_UPDATE len=4 (conn) incr=16384
Feb 01 14:03:04 [2701602]: http2: server read frame WINDOW_UPDATE stream=41 len=4 incr=16384
Feb 01 14:03:08 systemd-journald[121]: [🡕] Suppressed 6156 messages from service
Feb 01 14:03:08 [2701602]: http2: server read frame WINDOW_UPDATE len=4 (conn) incr=16384
Feb 01 14:03:08 [2701602]: http2: server read frame WINDOW_UPDATE stream=37 len=4 incr=16384
Feb 01 14:03:08 [2701602]: http2: server read frame WINDOW_UPDATE len=4 (conn) incr=16384
Feb 01 14:03:08 [2701602]: http2: server read frame WINDOW_UPDATE stream=39 len=4 incr=16384
Feb 01 14:03:08 [2701602]: http2: server read frame WINDOW_UPDATE len=4 (conn) incr=16384
Feb 01 14:03:08 [2701602]: http2: server read frame WINDOW_UPDATE stream=39 len=4 incr=16384
Feb 01 14:03:08 [2701602]: http2: server read frame WINDOW_UPDATE len=4 (conn) incr=16384
Feb 01 14:03:08 [2701602]: http2: server read frame WINDOW_UPDATE stream=37 len=4 incr=16384
Feb 01 14:03:08 [2701602]: http2: server read frame WINDOW_UPDATE len=4 (conn) incr=16384
Feb 01 14:03:08 [2701602]: http2: server read frame WINDOW_UPDATE stream=39 len=4 incr=16384
Feb 01 14:03:08 [2701602]: http2: server read frame WINDOW_UPDATE len=4 (conn) incr=16384
Feb 01 14:03:08 [2701602]: http2: server read frame WINDOW_UPDATE stream=39 len=4 incr=16384

Sounds like #28732

@mknyszek
Copy link
Contributor

mknyszek commented Feb 1, 2024

CC @neild

@mknyszek mknyszek added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Feb 1, 2024
@mknyszek mknyszek added this to the Backlog milestone Feb 1, 2024
@mknyszek mknyszek changed the title net/http2: Remote end of long POST request randomly closes net/http: remote end of long POST request randomly closes when using http2 Feb 1, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
None yet
Milestone
Backlog
Development

No branches or pull requests
1 participant
@mknyszek