net/http: ServeContent()/ServeFile() doesn't return expected response when WriteTimeout happens

[fuweid]

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

$ go version
go version go1.15.7 linux/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
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/root/.cache/go-build"
GOENV="/root/.config/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GOMODCACHE="/root/go/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/root/go"
GOPRIVATE=""
GOPROXY="https://goproxy.cn,direct"
GOROOT="/usr/local/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
AR="ar"
CC="gcc"
CXX="g++"
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 -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build783936539=/tmp/go-build -gno-record-gcc-switches"

What did you do?

We are running simple proxy for retrieving blob files. Just in case, we set WriteTimeout for proxy server. The logic is described by the following code.

package main

import (
	"log"
	"net/http"
	"time"
)

// The content of filePath is in JSON format.
//
//
// {"architecture":"amd64","config":{"Hostname":"","Domainname":"","User":"0","AttachStdin":false,"AttachStdout":false,"AttachStderr":false,"Tty":false,"OpenStdin":false,"StdinOnce":false,"Env":["PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin","SSL_CERT_FILE=/etc/ssl/certs/ca-certificates.crt"],"Cmd":null,"Image":"sha256:cbdac00ef1904d59ccd11add20108257111b8f65a854170f2d31caa78c4bb1b2","Volumes":null,"WorkingDir":"/","Entrypoint":["/go-runner"],"OnBuild":null,"Labels":{"description":"go based runner for distroless scenarios","maintainers":"Kubernetes Authors"}},"container_config":{"Hostname":"","Domainname":"","User":"0","AttachStdin":false,"AttachStdout":false,"AttachStderr":false,"Tty":false,"OpenStdin":false,"StdinOnce":false,"Env":["PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin","SSL_CERT_FILE=/etc/ssl/certs/ca-certificates.crt"],"Cmd":["/bin/sh","-c","#(nop) COPY file:7fed31705f1c51a2c3f437d928dc68009c048406d85a556147a4a7aea5b15f7c in /usr/local/bin/kube-apiserver "],"Image":"sha256:cbdac00ef1904d59ccd11add20108257111b8f65a854170f2d31caa78c4bb1b2","Volumes":null,"WorkingDir":"/","Entrypoint":["/go-runner"],"OnBuild":null,"Labels":{"description":"go based runner for distroless scenarios","maintainers":"Kubernetes Authors"}},"created":"2020-12-18T12:21:06.637698261Z","docker_version":"19.03.8","history":[{"created":"1970-01-01T00:00:00Z","author":"Bazel","created_by":"bazel build ..."},{"created":"2020-11-24T01:39:04.46965334Z","created_by":"LABEL maintainers=Kubernetes Authors","comment":"buildkit.dockerfile.v0","empty_layer":true},{"created":"2020-11-24T01:39:04.46965334Z","created_by":"LABEL description=go based runner for distroless scenarios","comment":"buildkit.dockerfile.v0","empty_layer":true},{"created":"2020-11-24T01:39:04.46965334Z","created_by":"WORKDIR /","comment":"buildkit.dockerfile.v0","empty_layer":true},{"created":"2020-11-24T01:39:04.46965334Z","created_by":"COPY /workspace/go-runner . # buildkit","comment":"buildkit.dockerfile.v0"},{"created":"2020-11-24T01:39:04.46965334Z","created_by":"ENTRYPOINT [\"/go-runner\"]","comment":"buildkit.dockerfile.v0","empty_layer":true},{"created":"2020-12-18T12:21:06.637698261Z","created_by":"/bin/sh -c #(nop) COPY file:7fed31705f1c51a2c3f437d928dc68009c048406d85a556147a4a7aea5b15f7c in /usr/local/bin/kube-apiserver "}],"os":"linux","rootfs":{"type":"layers","diff_ids":["sha256:e7ee84ae4d1363ccf59b14bf34a79c245705dfd55429918b63c754d84c85d904","sha256:597f1090d8e9bd4f1847ea4b72a3c3ea1f0997011120816c9dae2fe858077b32","sha256:007430fdb20c04acd56f66f3032b747f8e5ac47edb6855a37ae9f37d7be15b81"]}}#
var filePath = "/tmp/75c7f711208082c548b935ab31e681ea30acccdce6b7abeecabae5bbfd326627"

type handler struct{}

func (h *handler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
	time.Sleep(2 * time.Second) // handle some logic
	http.ServeFile(w, r, filePath)
}

func main() {
	s := &http.Server{
		Addr:         "127.0.0.1:9999",
		Handler:      &handler{},
		WriteTimeout: 1 * time.Second,
	}
	log.Fatal(s.ListenAndServe())
}

If the handler takes time and the WriteTimeout happens, the http.ServeFile still can sends the data without HTTP Status line and header. We use the following code as client to reproduce the issue.

package main

import (
	"io"
	"io/ioutil"
	"net/http"
)

func main() {
	resp, err := http.Get("http://127.0.0.1:9999")
	if err != nil {
		panic(err)
	}
	defer resp.Body.Close()
	io.Copy(ioutil.Discard, resp.Body)
}

The result is like:

➜  /tmp go run client.go
panic: Get "http://127.0.0.1:9999": net/http: HTTP/1.x transport connection broken: malformed HTTP status code "based"

goroutine 1 [running]:
main.main()
        /tmp/client.go:12 +0x125
exit status 2

Go HTTP Server will call SetWriteDeadline() in readRequest. When we call http.ServeContent/ServeFile to write response, the go runtime will use (*response).ReadFrom to make it fast.

But we found that the chunkWriter.flush doesn't return error so that the ReadFrom doesn't know if the flush works.

// https://github.com/golang/go/blob/go1.15.7/src/net/http/server.go#L581

// ReadFrom is here to optimize copying from an *os.File regular file
// to a *net.TCPConn with sendfile.
func (w *response) ReadFrom(src io.Reader) (n int64, err error) {
       ...
       ...
       w.w.Flush()  // get rid of any previous writes
       w.cw.flush() // make sure Header is written; flush data to rwc
      ...
}

In this case, both the status and the header are lost because netpoll checker return I/O timeout. But the server still send data to client and the data is not valid http response, called malformed HTTP status. The WriteTimeout doesn't work well in ServeContent/ServeFile mode and return confusing response. I think it should be aligned with normal mode, described by the following code.

// server.go
package main

import (
        "log"
        "net/http"
        "time"
)

type handler struct{}

func (h *handler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
        time.Sleep(2 * time.Second) // handle some logic
        w.Write([]byte("oops"))
}

func main() {
        s := &http.Server{
                Addr:         "127.0.0.1:9999",
                Handler:      &handler{},
                WriteTimeout: 1 * time.Second,
        }
        log.Fatal(s.ListenAndServe())
}

// bash shell
➜  /tmp go run client.go
panic: Get "http://127.0.0.1:9999": EOF

goroutine 1 [running]:
main.main()
        /tmp/client.go:12 +0x125
exit status 2

What did you expect to see?

I expected to see EOF error

What did you see instead?

I saw that malformed HTTP status.

cc @zhuangqh @Ace-Tang

[yyb196]

We have bothered by this bug for a long time.

After dig into code I found that when response writing headers, it ultimately using FD.Write which then called pollDesc.prepareWrite where to check if writer connection has expired. but when response writing body it using io.Copy which ultimately called TCPConn.readFrom who using sendFile to transfer file but don't check if the connection has expired. That's how come the http headers don't transfer to client but the body are.

I think we should invoke dstFD.pd.prepare to check if the connection has expired at:

go/src/internal/poll/sendfile_linux.go

Line 20 in ecf4ebf

dst := int(dstFD.Sysfd)

[ThunderYe]

Maybe the patch of " w.cw.flush() " is better, when the Head failed to send , shoud just cancel whole respose procedure，for a body withoud Head is malformed of HTTP protocal at all。

[gopherbot]

Change https://golang.org/cl/285914 mentions this issue: internal/poll: netpollcheckerr before sendfile

[ianlancetaylor]

@dmitshur @toothrot @cagedmantis This issue might be worthy of a backport, so we may want to consider adding CL 285914 to 1.16 even though rc1 is out. I'd like @neild to take a look at the test, though. Thanks.

[odeke-em]

Roger that, I've added feedback to improve the test :-)

[fuweid]

Roger that, I've added feedback to improve the test :-)

@odeke-em, Thanks! I updated it and please take a look. Thank you~

[dmitshur]

@neild Are you able to take a look at the latest comments in CL 285914, since there's little time left in the Go1.16 milestone? Thanks.