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

fuweid · 2021-01-21T10:17:42Z

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

The text was updated successfully, but these errors were encountered:

yyb196 · 2021-01-21T14:40:33Z

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 · 2021-01-22T08:08:42Z

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 · 2021-01-24T11:03:33Z

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

ianlancetaylor · 2021-01-27T23:11:10Z

@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 · 2021-02-01T22:42:14Z

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

fuweid · 2021-02-02T02:48:50Z

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

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

dmitshur · 2021-02-10T19:44:59Z

@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.

odeke-em · 2021-02-16T17:30:13Z

As per the comment by Ian in #43822 (comment), this issue is a worthy candidate. @gopherbot please backport this issue.

gopherbot · 2021-02-16T17:47:24Z

Backport issue(s) opened: #44293 (for 1.14), #44294 (for 1.15).

Remember to create the cherry-pick CL(s) as soon as the patch is submitted to master, according to https://golang.org/wiki/MinorReleases.

gopherbot · 2021-02-25T19:53:34Z

Change https://golang.org/cl/296530 mentions this issue: [release-branch.go1.15] internal/poll: netpollcheckerr before sendfile

In net/http package, the ServeContent/ServeFile doesn't check the I/O timeout error from chunkWriter or *net.TCPConn, which means that both HTTP status and headers might be missing when WriteTimeout happens. If the poll.SendFile() doesn't check the *poll.FD state before sending data, the client will only receive the response body with status and report "malformed http response/status code". This patch is to enable netpollcheckerr before sendfile, which should align with normal *poll.FD.Write() and Splice(). For #43822 Fixes #44294 Change-Id: I32517e3f261bab883a58b577b813ef189214b954 Reviewed-on: https://go-review.googlesource.com/c/go/+/285914 Reviewed-by: Emmanuel Odeke <emmanuel@orijtech.com> Trust: Emmanuel Odeke <emmanuel@orijtech.com> Trust: Bryan C. Mills <bcmills@google.com> Run-TryBot: Emmanuel Odeke <emmanuel@orijtech.com> (cherry picked from commit f0d23c9) Reviewed-on: https://go-review.googlesource.com/c/go/+/296530 Trust: Ian Lance Taylor <iant@golang.org> Run-TryBot: Ian Lance Taylor <iant@golang.org> TryBot-Result: Go Bot <gobot@golang.org>

fuweid changed the title ~~net/http: ServeContent()/ServeFile() doesn't return expected response when WriteTimeout~~ net/http: ServeContent()/ServeFile() doesn't return expected response when WriteTimeout happens Jan 21, 2021

seankhliao added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Jan 21, 2021

dmitshur added this to the Go1.16 milestone Jan 27, 2021

dmitshur assigned neild Feb 11, 2021

dmitshur added the NeedsDecision Feedback is required from experts, contributors, and/or the community before a change can be made. label Feb 11, 2021

gopherbot removed the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Feb 11, 2021

bep mentioned this issue Feb 13, 2021

html/template: data race in Execute #39807

Closed

gopherbot closed this as completed in f0d23c9 Feb 16, 2021

dmitshur added NeedsFix The path to resolution is known, but the work has not been done. and removed NeedsDecision Feedback is required from experts, contributors, and/or the community before a change can be made. labels Feb 16, 2021

dmitshur assigned odeke-em Feb 16, 2021

gopherbot mentioned this issue Feb 16, 2021

net/http: ServeContent()/ServeFile() doesn't return expected response when WriteTimeout happens [1.14 backport] #44293

Closed

gopherbot mentioned this issue Feb 16, 2021

net/http: ServeContent()/ServeFile() doesn't return expected response when WriteTimeout happens [1.15 backport] #44294

Closed

golang locked and limited conversation to collaborators Feb 25, 2022

gopherbot added the FrozenDueToAge label Feb 25, 2022

rsc unassigned neild and odeke-em Jun 23, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

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

fuweid commented Jan 21, 2021 •

edited

yyb196 commented Jan 21, 2021

ThunderYe commented Jan 22, 2021

gopherbot commented Jan 24, 2021

ianlancetaylor commented Jan 27, 2021

odeke-em commented Feb 1, 2021

fuweid commented Feb 2, 2021

dmitshur commented Feb 10, 2021

odeke-em commented Feb 16, 2021

gopherbot commented Feb 16, 2021

gopherbot commented Feb 25, 2021

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

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

Comments

fuweid commented Jan 21, 2021 • edited

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

Does this issue reproduce with the latest release?

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

What did you do?

What did you expect to see?

What did you see instead?

yyb196 commented Jan 21, 2021

ThunderYe commented Jan 22, 2021

gopherbot commented Jan 24, 2021

ianlancetaylor commented Jan 27, 2021

odeke-em commented Feb 1, 2021

fuweid commented Feb 2, 2021

dmitshur commented Feb 10, 2021

odeke-em commented Feb 16, 2021

gopherbot commented Feb 16, 2021

gopherbot commented Feb 25, 2021

fuweid commented Jan 21, 2021 •

edited

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

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