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: not all server Push responses are being sent #30866

Closed
AndreasBackx opened this issue Mar 15, 2019 · 5 comments
Closed

x/net/http2: not all server Push responses are being sent #30866

AndreasBackx opened this issue Mar 15, 2019 · 5 comments
Labels
NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone

Comments

@AndreasBackx
Copy link

AndreasBackx commented Mar 15, 2019

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

$ go version
go version go1.12.1 darwin/amd64

Does this issue reproduce with the latest release?

Yes.

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

go env Output
$ go env
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/Andreas/Library/Caches/go-build"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOOS="darwin"
GOPATH="/Users/Andreas/Development/Go"
GOPROXY=""
GORACE=""
GOROOT="/usr/local/Cellar/go/1.12.1/libexec"
GOTMPDIR=""
GOTOOLDIR="/usr/local/Cellar/go/1.12.1/libexec/pkg/tool/darwin_amd64"
GCCGO="gccgo"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD=""
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/dw/wtbd233j0yd8vzjzlfz1wz1w0000gn/T/go-build928352300=/tmp/go-build -gno-record-gcc-switches -fno-common"

This also occurs on Linux with kernel 5.0.

What did you do?

I setup a Golang server that pushed 18 files of around 200kB each. When using Chromium, these are all pushed correctly and Chromium can seemingly read all of them. However, when using Java 11's HttpClient, this is not the case. It won't read about 5 (give or take) of the pushed responses. Though, the Java HttpClient will always read them when a different server is used, in my test case I used Node.

Golang server: https://github.com/AndreasBackx/golang-bug-server-push-go
Node server: https://github.com/AndreasBackx/golang-bug-server-push-node
Kotlin client: https://github.com/AndreasBackx/golang-bug-server-push-kotlin
See their README on how to run them.

In order to reproduce this, run the Golang server and run the Kotlin client and you will see an output that looks like this:

Kotlin client output with Golang server.
Starting... 
pushPromiseRequest: https://localhost:4430/public/video_01.m4s 
pushPromiseRequest: https://localhost:4430/public/video_02.m4s 
pushPromiseRequest: https://localhost:4430/public/video_03.m4s 
pushPromiseRequest: https://localhost:4430/public/video_04.m4s 
pushPromiseRequest: https://localhost:4430/public/video_05.m4s 
pushPromiseRequest: https://localhost:4430/public/video_06.m4s 
pushPromiseRequest: https://localhost:4430/public/video_07.m4s 
pushPromiseRequest: https://localhost:4430/public/video_08.m4s 
pushPromiseRequest: https://localhost:4430/public/video_09.m4s 
pushPromiseRequest: https://localhost:4430/public/video_10.m4s 
pushPromiseRequest: https://localhost:4430/public/video_11.m4s 
pushPromiseRequest: https://localhost:4430/public/video_12.m4s 
pushPromiseRequest: https://localhost:4430/public/video_13.m4s 
pushPromiseRequest: https://localhost:4430/public/video_14.m4s 
pushPromiseRequest: https://localhost:4430/public/video_15.m4s 
pushPromiseRequest: https://localhost:4430/public/video_16.m4s 
pushPromiseRequest: https://localhost:4430/public/video_17.m4s 
pushPromiseRequest: https://localhost:4430/public/video_18.m4s 
1/18 https://localhost:4430/public/video_13.m4s 
2/18 https://localhost:4430/public/video_17.m4s 
3/18 https://localhost:4430/public/video_18.m4s 
4/18 https://localhost:4430/public/video_16.m4s 
5/18 https://localhost:4430/public/video_15.m4s 
6/18 https://localhost:4430/public/video_12.m4s 
7/18 https://localhost:4430/public/video_14.m4s 
8/18 https://localhost:4430/public/video_11.m4s 
9/18 https://localhost:4430/public/video_09.m4s 
10/18 https://localhost:4430/public/video_10.m4s 

Though when using the Node server, it works just fine and it accepts all of the responses from the push promises:

Kotlin client output with Node server.
Starting... 
pushPromiseRequest: https://localhost:4430/public/video_01.m4s 
pushPromiseRequest: https://localhost:4430/public/video_02.m4s 
pushPromiseRequest: https://localhost:4430/public/video_03.m4s 
pushPromiseRequest: https://localhost:4430/public/video_04.m4s 
pushPromiseRequest: https://localhost:4430/public/video_05.m4s 
pushPromiseRequest: https://localhost:4430/public/video_06.m4s 
pushPromiseRequest: https://localhost:4430/public/video_07.m4s 
pushPromiseRequest: https://localhost:4430/public/video_08.m4s 
pushPromiseRequest: https://localhost:4430/public/video_09.m4s 
pushPromiseRequest: https://localhost:4430/public/video_10.m4s 
pushPromiseRequest: https://localhost:4430/public/video_11.m4s 
pushPromiseRequest: https://localhost:4430/public/video_12.m4s 
pushPromiseRequest: https://localhost:4430/public/video_13.m4s 
pushPromiseRequest: https://localhost:4430/public/video_14.m4s 
pushPromiseRequest: https://localhost:4430/public/video_15.m4s 
pushPromiseRequest: https://localhost:4430/public/video_16.m4s 
pushPromiseRequest: https://localhost:4430/public/video_17.m4s 
pushPromiseRequest: https://localhost:4430/public/video_18.m4s 
1/18 https://localhost:4430/public/video_11.m4s 
2/18 https://localhost:4430/public/video_01.m4s 
3/18 https://localhost:4430/public/video_09.m4s 
4/18 https://localhost:4430/public/video_07.m4s 
5/18 https://localhost:4430/public/video_12.m4s 
6/18 https://localhost:4430/public/video_13.m4s 
7/18 https://localhost:4430/public/video_06.m4s 
8/18 https://localhost:4430/public/video_18.m4s 
9/18 https://localhost:4430/public/video_17.m4s 
10/18 https://localhost:4430/public/video_16.m4s 
11/18 https://localhost:4430/public/video_15.m4s 
12/18 https://localhost:4430/public/video_14.m4s 
13/18 https://localhost:4430/public/video_10.m4s 
14/18 https://localhost:4430/public/video_05.m4s 
15/18 https://localhost:4430/public/video_08.m4s 
16/18 https://localhost:4430/public/video_04.m4s 
17/18 https://localhost:4430/public/video_03.m4s 
18/18 https://localhost:4430/public/video_02.m4s 

What did you expect to see?

All push promises and responses to be read. See the Kotlint client output with the Node server above.

What did you see instead?

Only the push promises are all read, not all of the responses are read.

You can see that when you debug the Golang server that the Handler of the http.FileServer is being called for all of them. Though the logs that are printed after http.Handler.ServeHTTP are not printed for the bodies that could not have been read.

This indicates that the http.Handler.ServeHTTP is about to get called:

[...] GET /public/video_13.m4s

This indicates that the http.Handler.ServeHTTP was called and that a status code was successfully set and that it was the first of the 18 to be sent:

[200]: GET /public/video_13.m4s (1/18)

Though this last one does not occur for all 18 pushes. In the logs it only happens for 10 of them.

Golang server output.
2019/03/15 16:30:03 Listening...
2019/03/15 16:30:09 Pushing /public/video_01.m4s...
2019/03/15 16:30:09 [...] GET /public/video_01.m4s
2019/03/15 16:30:09 Pushing /public/video_02.m4s...
2019/03/15 16:30:09 [...] GET /public/video_02.m4s
2019/03/15 16:30:09 Pushing /public/video_03.m4s...
2019/03/15 16:30:09 [...] GET /public/video_03.m4s
2019/03/15 16:30:09 Pushing /public/video_04.m4s...
2019/03/15 16:30:09 [...] GET /public/video_04.m4s
2019/03/15 16:30:09 Pushing /public/video_05.m4s...
2019/03/15 16:30:09 [...] GET /public/video_05.m4s
2019/03/15 16:30:09 Pushing /public/video_06.m4s...
2019/03/15 16:30:09 [...] GET /public/video_06.m4s
2019/03/15 16:30:09 Pushing /public/video_07.m4s...
2019/03/15 16:30:09 [...] GET /public/video_07.m4s
2019/03/15 16:30:09 Pushing /public/video_08.m4s...
2019/03/15 16:30:09 [...] GET /public/video_08.m4s
2019/03/15 16:30:09 Pushing /public/video_09.m4s...
2019/03/15 16:30:09 [...] GET /public/video_09.m4s
2019/03/15 16:30:09 Pushing /public/video_10.m4s...
2019/03/15 16:30:09 [...] GET /public/video_10.m4s
2019/03/15 16:30:09 Pushing /public/video_11.m4s...
2019/03/15 16:30:09 [...] GET /public/video_11.m4s
2019/03/15 16:30:09 Pushing /public/video_12.m4s...
2019/03/15 16:30:09 [...] GET /public/video_12.m4s
2019/03/15 16:30:09 Pushing /public/video_13.m4s...
2019/03/15 16:30:09 [...] GET /public/video_13.m4s
2019/03/15 16:30:09 Writing status 200
2019/03/15 16:30:09 Pushing /public/video_14.m4s...
2019/03/15 16:30:09 Writing status 200
2019/03/15 16:30:09 Writing status 200
2019/03/15 16:30:09 Pushing /public/video_15.m4s...
2019/03/15 16:30:09 [...] GET /public/video_15.m4s
2019/03/15 16:30:09 Pushing /public/video_16.m4s...
2019/03/15 16:30:09 Writing status 200
2019/03/15 16:30:09 [...] GET /public/video_16.m4s
2019/03/15 16:30:09 Writing status 200
2019/03/15 16:30:09 Writing status 200
2019/03/15 16:30:09 Writing status 200
2019/03/15 16:30:09 Writing status 200
2019/03/15 16:30:09 [...] GET /public/video_14.m4s
2019/03/15 16:30:09 Writing status 200
2019/03/15 16:30:09 Writing status 200
2019/03/15 16:30:09 Pushing /public/video_17.m4s...
2019/03/15 16:30:09 Writing status 200
2019/03/15 16:30:09 Writing status 200
2019/03/15 16:30:09 Writing status 200
2019/03/15 16:30:09 Writing status 200
2019/03/15 16:30:09 Writing status 200
2019/03/15 16:30:09 Writing status 200
2019/03/15 16:30:09 [...] GET /public/video_17.m4s
2019/03/15 16:30:09 Pushing /public/video_18.m4s...
2019/03/15 16:30:09 [200]: GET /public/video_13.m4s (1/18)
2019/03/15 16:30:09 Writing status 200
2019/03/15 16:30:09 [...] GET /public/video_18.m4s
2019/03/15 16:30:09 Writing status 200
2019/03/15 16:30:09 [200]: GET /public/video_17.m4s (2/18)
2019/03/15 16:30:09 [200]: GET /public/video_18.m4s (3/18)
2019/03/15 16:30:09 [200]: GET /public/video_16.m4s (4/18)
2019/03/15 16:30:09 [200]: GET /public/video_15.m4s (5/18)
2019/03/15 16:30:09 [200]: GET /public/video_12.m4s (6/18)
2019/03/15 16:30:09 [200]: GET /public/video_14.m4s (7/18)
2019/03/15 16:30:09 [200]: GET /public/video_11.m4s (8/18)
2019/03/15 16:30:09 [200]: GET /public/video_09.m4s (9/18)
2019/03/15 16:30:09 [200]: GET /public/video_10.m4s (10/18)
@AndreasBackx
Copy link
Author

I would also like to say that with smaller files, it seems to be delivered more often. Though the size of these files is not large at all (about 200kB each). I wonder what happens when these files are multiple MBs.

@odeke-em odeke-em changed the title HTTP2 Server Push responses not all being sent x/net/http2: not all server Push responses are being sent Mar 16, 2019
@odeke-em
Copy link
Member

Thank you for this report @AndreasBackx and welcome to the Go project!

So to help distill the problem for Go, I have adapted your original code and made it a standalone server and client which can let reproducers and testers make requests to it and verify that things are running

package main

import (
	"crypto/tls"
	"fmt"
	"io"
	"io/ioutil"
	"log"
	"net/http"
	"net/http/httptest"
	"net/http/httputil"
	"os"
	"path/filepath"
	"strings"
	"time"

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

var paths []string

func pushHandler(writer http.ResponseWriter, request *http.Request) {
	defer func() {
		blob, _ := httputil.DumpRequest(request, true)
		fmt.Printf("\nRequest In:\n%s\n", blob)
	}()

	pusher, supported := writer.(http.Pusher)
	if !supported {
		writer.WriteHeader(http.StatusHTTPVersionNotSupported)
		writer.Write([]byte("HTTP/2 push not supported."))
		return
	}

	html := "<html><body><h1>Golang Server Push</h1>"

	errCount := 0
	for _, path := range paths {
		log.Printf("Pushing %s...\n", path)
		if err := pusher.Push(path, nil); err != nil {
			errCount++
			log.Printf("Failed to push: %v", err)
			continue
		}
		html += fmt.Sprintf("<video src=\"%s\"></video>", path)
	}

	fmt.Fprint(writer, html)
}

type responseWriterLogger struct {
	http.ResponseWriter
	status int
}

func (w *responseWriterLogger) WriteHeader(status int) {
	log.Printf("Writing status %d\n", status)
	w.status = status
	w.ResponseWriter.WriteHeader(status)
}

func wrapFileServer(next http.Handler) http.HandlerFunc {
	return func(w http.ResponseWriter, r *http.Request) {
		wl := &responseWriterLogger{ResponseWriter: w}
		log.Printf("[...] %s %s\n", r.Method, r.URL)
		next.ServeHTTP(wl, r)
		log.Printf("[%d]: %s %s\n", wl.status, r.Method, r.URL)
	}
}

func main() {
	// 1. Generate the files.
	n := 30
	publicDir := "public"
	if err := os.MkdirAll(publicDir, 0755); err != nil {
		log.Fatalf("Failed to create the the directory for the files: %v", err)
	}
	// Remember to clean up on exit.
	defer os.RemoveAll(publicDir)

	for i := 0; i < n; i++ {
		fullPath := filepath.Join(publicDir, fmt.Sprintf("%d.txt", i))
		payload := strings.Repeat(fmt.Sprintf("%d", i+1), 300<<10) // Make them 300kB
		if err := ioutil.WriteFile(fullPath, []byte(payload), 0655); err != nil {
			log.Fatalf("Failed to create %s: %v", fullPath, err)
		}
		paths = append(paths, filepath.Join("/", fullPath))
	}

	// 2. Now run the server.
	relPublicDir := "/" + publicDir + "/"
	mux := http.NewServeMux()
	mux.Handle(relPublicDir, wrapFileServer(http.StripPrefix(relPublicDir, http.FileServer(http.Dir(publicDir+"/")))))
	mux.HandleFunc("/push", pushHandler)

	cst := httptest.NewUnstartedServer(mux)
	http2.ConfigureServer(cst.Config, new(http2.Server))
	cst.TLS = cst.Config.TLSConfig
	cst.StartTLS()
	defer cst.Close()

	// 3. Initiate a request using the HTTP/2.0 Go client.
	tr := &http.Transport{
		TLSClientConfig: &tls.Config{
			InsecureSkipVerify: true,
			NextProtos:         []string{"h2"},
		},
	}
	http2.ConfigureTransport(tr)
	client := &http.Client{Transport: tr}

	res, err := client.Get(cst.URL + "/push")
	if err != nil {
		log.Fatalf("Failed to make client HTTP request: %v", err)
	}
	io.Copy(os.Stdout, res.Body)
	res.Body.Close()
	fmt.Printf("\n\nAnd the server URL is: %s\n", cst.URL)

	// Remove to end repro immediately or keep to test the server
	// out with your browser or HTTP clients.
	for {
		<-time.After(10 * time.Second)
	}
}

Results

I would also like to say that with smaller files, it seems to be delivered more often. Though the size of these files is not large at all (about 200kB each). I wonder what happens when these files are multiple MBs.

In my adaptation, I generated 30 files each of size 300kB but Chrome shows all of them downloaded as per this screenshot
Screen Shot 2019-03-15 at 9 59 53 PM

I'll also page @bradfitz @rakyll @tombergan to take a look as well and examine what could be up for your setup

@odeke-em odeke-em added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Mar 16, 2019
@AndreasBackx
Copy link
Author

AndreasBackx commented Mar 16, 2019

@odeke-em

So to help distill the problem for Go, I have adapted your original code and made it a standalone server and client which can let reproducers and testers make requests to it and verify that things are running

I couldn't find any information on there being an HTTP/2 client for Go which is why I was using a Kotlin/Java client. I saw that HTTP2 Server Push was not yet fully supported seemingly #18594 and failed to find any resources regarding it besides the blog post mentioning server-side support.

In my adaptation, I generated 30 files each of size 300kB but Chrome shows all of them downloaded as per this screenshot

I mentioned in the original issue that Chromium always downloads all of them seemingly correctly. I have experienced the same issue with the Python library hyper instead of the Java client, though I did not include a sample.

ssl_context = ssl.create_default_context(
    # Accept self-signed certificates.
    # Actually meant for client authentication on server side, but it works.
    ssl.Purpose.CLIENT_AUTH,
)
ssl_context.set_alpn_protocols(['h2'])
connection = HTTPConnection(
    host=self.host,
    port=self.port,
    secure=True,
    enable_push=True,
    ssl_context=ssl_context,
)
connection.request('GET', '/push')
response = connection.get_response()

for push in connection.get_pushes(capture_all=True):
    push_response = push.get_response()

response.close()

The push.get_response() times out when using the Golang client, but works seemingly fine when using the Node server. This was on the latest commit from the development branch. I did include the sample as I thought it would be better to use an HTTP client that was assumed to be stable. Though, it would've been wise to at least mention it that I tried two different clients.

You say you added a client in your adaptation, but I don't see any any results from what that did as you only showed Chromium's results?

@AndreasBackx
Copy link
Author

I would like to add that I would not recommend using Hyper for testing the possible bug here as I found that there was a large amount of jitter (up to 1 second) when using Hyper compared to using Java/Kotlin. I could not explain why, but it probably has to do with the fact that the library is not finished and is seemingly no longer being maintained. I did not experience any jitter when using the Java/Kotlin client.

@mitar
Copy link
Contributor

mitar commented Feb 24, 2022

It could be that the browser cancelled some of the pushes because it already had them cached.

@seankhliao seankhliao added this to the Unplanned milestone Aug 27, 2022
@AndreasBackx AndreasBackx closed this as not planned Won't fix, can't repro, duplicate, stale Feb 10, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
None yet
Development

No branches or pull requests

4 participants