net/http: error dropped when header read times out

[period331]

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

$ go version
go version go1.19 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="on"
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/work/.cache/go-build"
GOENV="/home/work/.config/go/env"
GOEXE=""
GOEXPERIMENT=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GOMODCACHE="/home/work/gopath/pkg/mod"
GONOPROXY=""
GONOSUMDB="*"
GOOS="linux"
GOPATH="/home/work/gopath"
GOPRIVATE=""
GOPROXY=""
GOROOT="/home/work/gopath/src/go-env/go1-19-linux-amd64"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/home/work/gopath/src/go-env/go1-19-linux-amd64/pkg/tool/linux_amd64"
GOVCS=""
GOVERSION="go1.19"
GCCGO="gccgo"
GOAMD64="v1"
AR="ar"
CC="/opt/compiler/gcc-8.2/bin/gcc"
CXX="/opt/compiler/gcc-8.2/bin/g++"
CGO_ENABLED="1"
GOMOD="/dev/null"
GOWORK=""
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 -Wl,--no-gc-sections -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build3130045008=/tmp/go-build -gno-record-gcc-switches"

What did you do?

package main

import (
	"context"
	"fmt"
	"log"
	"net"
	"net/http"
	"os"
	"time"
)

type handler struct {
}

func (h *handler) ServeHTTP(w http.ResponseWriter, req *http.Request) {
	w.Write([]byte("Hello World"))
}

func newServer(port int) *http.Server {
	s := &http.Server{
		Addr:           fmt.Sprintf(":%d", port),
		Handler:        &handler{},
		ReadTimeout:    100 * time.Millisecond,
		WriteTimeout:   100 * time.Millisecond,
		MaxHeaderBytes: 1 << 20,
		ErrorLog:       log.New(os.Stderr, "", log.LstdFlags),
	}
	return s
}

func send(port int) {
	conn, err := net.Dial("tcp", fmt.Sprintf("127.0.0.1:%d", port))
	if err != nil {
		fmt.Println(err)
		return
	}

	n, e := conn.Write([]byte("GET / HTTP/1.1\r\n"))
	fmt.Println("send first line", n, e)

	n, e = conn.Write([]byte("Host: www.google.com\r\n"))
	fmt.Println("send host", n, e)

	n, e = conn.Write([]byte("Host1"))
	fmt.Println("send part header", n, e)

	// more than ReadTimeout
	time.Sleep(time.Millisecond * 110)

	buf := make([]byte, 8192)
	n, e = conn.Read(buf)
	fmt.Println("read resp", n, e)
	fmt.Println("print resp", "`"+string(buf)+"`")
	time.Sleep(time.Millisecond * 200)
	fmt.Println("conn close", conn.Close())
}

func main() {
	port := 12101
	svr := newServer(port)
	go func() {
		fmt.Println(svr.ListenAndServe())
	}()

	// wait server start
	time.Sleep(time.Second * 1)
	go send(port)

	time.Sleep(time.Second * 1)
	fmt.Println("server shutdown", svr.Shutdown(context.Background()))
	time.Sleep(time.Second * 1)
}

What did you expect to see?

send first line 16 <nil>
send host 22 <nil>
send part header 5 <nil>
read resp 0 EOF
print resp ``
conn close <nil>
http: Server closed
server shutdown <nil>

and log read tcp 127.0.0.1:12101->127.0.0.1:xxx: i/o timeout

What did you see instead?

send first line 16 <nil>
send host 22 <nil>
send part header 5 <nil>
read resp 103 <nil>
print resp `HTTP/1.1 400 Bad Request
Content-Type: text/plain; charset=utf-8
Connection: close

400 Bad Request`
conn close <nil>
http: Server closed
server shutdown <nil>

Because 'bufio. ReadLine()' dropped the error, causing http.server to return '400 Bad Request'

[ZekeLu]

The OP means that bufio.(*Reader).ReadLine discards the error when the line is not empty. This behavior is documented:

ReadLine either returns a non-nil line or it returns an error, never both.

go/src/bufio/bufio.go

Lines 384 to 401 in 7e72d38

	// ReadLine is a low-level line-reading primitive. Most callers should use
	// ReadBytes('\n') or ReadString('\n') instead or use a Scanner.
	//
	// ReadLine tries to return a single line, not including the end-of-line bytes.
	// If the line was too long for the buffer then isPrefix is set and the
	// beginning of the line is returned. The rest of the line will be returned
	// from future calls. isPrefix will be false when returning the last fragment
	// of the line. The returned buffer is only valid until the next call to
	// ReadLine. ReadLine either returns a non-nil line or it returns an error,
	// never both.
	//
	// The text returned from ReadLine does not include the line end ("\r\n" or "\n").
	// No indication or error is given if the input ends without a final line end.
	// Calling UnreadByte after ReadLine will always unread the last byte read
	// (possibly a character belonging to the line end) even if that byte is not
	// part of the line returned by ReadLine.
	func (b *Reader) ReadLine() (line []byte, isPrefix bool, err error) {
	line, err = b.ReadSlice('\n')

In the OP's demo, after line 401 is executed, line is Host1, and err is read tcp 127.0.0.1:12101->127.0.0.1:51932: i/o timeout. Readline returns "Host1", false, nil in this case, so the request is considered as a bad request.

This is indeed confusing because the root cause is a header read timeout (we can modify the demo to create a valid request while preserve the timeout).

Please note that the current behavior of the http server is to ignore common net read error. So even if Readline returns the error, there is nothing more will be logged.

go/src/net/http/server.go

Lines 1936 to 1937 in 7e72d38

	case isCommonNetReadError(err):
	return // don't reply

I think the real question here is: How should we handle request header read timeout?

Here is the call stack into ReadLine in case it will help others looking into this issue further (on the current tip 7e72d38):

bufio.(*Reader).ReadLine
	src/bufio/bufio.go:403
net/textproto.(*Reader).readLineSlice
	src/net/textproto/reader.go:54
net/textproto.(*Reader).readContinuedLineSlice
	src/net/textproto/reader.go:127
net/textproto.(*Reader).ReadMIMEHeader
	src/net/textproto/reader.go:501
net/http.readRequest
	src/net/http/request.go:1085
net/http.(*conn).readRequest
	src/net/http/server.go:982
net/http.(*conn).serve
	src/net/http/server.go:1904
created by net/http.(*Server).Serve
	src/net/http/server.go:3072

[bcmills]

Please note that the current behavior of the http server is to ignore common net read error. So even if Readline returns the error, there is nothing more will be logged.
…
I think the real question here is: How should we handle request header read timeout?

(attn @neild)