golang / go

The Go programming language
https://go.dev
BSD 3-Clause "New" or "Revised" License
123.7k stars 17.62k forks source link

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

Closed AndreasBackx closed 8 months ago

AndreasBackx commented 5 years ago

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 commented 5 years ago

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 commented 5 years ago

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

AndreasBackx commented 5 years ago

@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 commented 5 years ago

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 commented 2 years ago

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