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

net/http: error dropped when header read times out #56390

Open
period331 opened this issue Oct 24, 2022 · 2 comments
Open

net/http: error dropped when header read times out #56390

period331 opened this issue Oct 24, 2022 · 2 comments
Labels
NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone

Comments

@period331
Copy link

period331 commented Oct 24, 2022

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
Copy link
Contributor

ZekeLu commented Oct 24, 2022

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 bcmills changed the title bufio: The ReadLine function discarded the error net/http: error dropped when header read times out Oct 24, 2022
@bcmills bcmills added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Oct 24, 2022
@bcmills bcmills added this to the Backlog milestone Oct 24, 2022
@bcmills
Copy link
Contributor

bcmills commented Oct 24, 2022

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)

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

3 participants