net/http: server waits for maxPostHandlerReadBytes of a chunked request before returning error

[winworm]

Please answer these questions before submitting your issue. Thanks!

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

go version go1.10.1 linux/amd64

Does this issue reproduce with the latest release?

yes

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

GOARCH="amd64"
GOBIN=""
GOCACHE="/home/qhyu/.cache/go-build"
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/home/qhyu/git/go"
GORACE=""
GOROOT="/home/qhyu/work/installed/go"
GOTMPDIR=""
GOTOOLDIR="/home/qhyu/work/installed/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
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-build281947105=/tmp/go-build -gno-record-gcc-switches"

What did you do?

use go http client to post a request to the go server use chunked protocol，the data send speed is constant

below is the client test code .

go func() {

		buf := make([]byte, 640)
		f, _ := os.Open(casefile)
		for {
			n, _ := f.Read(buf)
			if 0 == n {
				break
			}
			wr.Write(buf)
			// fmt.Println("write buf,sleep 20 ms")
			time.Sleep(time.Millisecond * 20)
		}
		tch <- time.Now()
		// fmt.Println("send tch complete")
		wr.Close()
	}()

	req := &http.Request{
		Method: "POST",
		ProtoMajor: 1,
		ProtoMinor: 1,
		URL: u,
		TransferEncoding: []string{"chunked"},
		Body: rd,
		Header: make(map[string][]string),
	}
	req.Header.Set("Content-Type", fmt.Sprintf("audio/%s;bit=16;rate=16000", tlvtype))
	queryparam := req.URL.Query()
	queryparam.Add("deviceId", "12348343948394343434898")
	queryparam.Add("lang", "zh")
	traceid := GetTraceId(16)
	queryparam.Add("traceId", traceid)
	req.URL.RawQuery = queryparam.Encode()
	client := http.DefaultClient
	resp, err := client.Do(req)
	if nil != err {
		fmt.Println("error =>", err.Error())
		return
	}
	body, err := ioutil.ReadAll(resp.Body)
	fmt.Printf("traceid: %s\tserver time: %s\talltime: %s\n", traceid, retm, alltime)
	if err == nil {
		resp.Body.Close()
	}

What did you expect to see?

when an error occur because of parameters check etc. the response will immediately get .

What did you see instead?

When the server validator fails, because of none request data was consumption, this should return an error code to the client directly, but now as a result, the client will wait for a long period of time （reading maxPostHandlerReadBytes bytes to flush response） to get the error code

[agnivade]

When the server validator fails,

What is this server validator ? Why will it fail ?

Can you please upload a complete and independent code sample ?

[bcmills]

(CC: @bradfitz, but awaiting more detail)

[bradfitz]

I don't really understand this bug.

Please post a complete pair of demonstration programs (a client & server), not just snippets. Perhaps that will make it more clear.

[winworm]

@agnivade What is this server validator ? Why will it fail ?
the server will check the deviceId parameter, if the deviceId is empty, the server normally return a response immediately, but if the client not sends data completely，the client will wait for a long time to read maxPostHandlerReadBytes bytes.

The full code of the server is then uploaded.

[everfighter]

client&server.zip
@bradfitz @agnivade

[everfighter]

Wireshark packet capture results show that the response was returned to the client 8s later，Client wants to receive response message immediately

[agnivade]

Thank you @everfighter /@winworm for providing the complete code.

[agnivade]

The issue is within your for loop in client.go. You are sleeping for a certain time which is causing the delay. Plus varying your buffer size will also change the response time. Just simply remove the for loop and do a _, err = io.Copy(wr, f). This effectively does what you are doing in the for loop. If you want to control the buffer size, use io.CopyBuffer.

I could not see anything related to maxPostHandlerReadBytes.

Feel free to comment if you disagree with the analysis.

[winworm]

thank you @agnivade
I know what you mean, if the client remove pause time, can really fast reply, but in my real application scenario, users transmit audio data (normal vocals, according to every 20 ms transmission frame data 640 bytes) is in accordance with such speed.
In the above example, a 10 s of audio transmission such as user data to the server, when 1 s in the server error happened, the direct return an error json, the json must be immediately returned to the client, but the real result is that the client needs to wait for about 8 s will receive a response.

below is some debug info of source code in server.go

func (w *response) finishRequest() {
	w.handlerDone.setTrue()

	if !w.wroteHeader {
		w.WriteHeader(StatusOK)
	}
	**start := time.Now()
	w.w.Flush()
	fmt.Println("chunkedwriterclose:"+time.Since(start).String())**
	putBufioWriter(w.w)
	w.cw.close()
	w.conn.bufw.Flush()
	w.conn.r.abortPendingRead()
	// Close the body (regardless of w.closeAfterReply) so we can
	// re-use its bufio.Reader later safely.
	start = time.Now()
	w.reqBody.Close()
	fmt.Println("w.reqBody.Close():"+time.Since(start).String())
	if w.req.MultipartForm != nil {
		w.req.MultipartForm.RemoveAll()
	}
}

w.w.Flush() will invoke the below method writeHeader(p []byte)

func (cw *chunkWriter) writeHeader(p []byte) {
.......
if w.req.ContentLength != 0 && !w.closeAfterReply {
		var discard, tooBig bool

		switch bdy := w.req.Body.(type) {
		case *expectContinueReader:
			if bdy.resp.wroteContinue {
				discard = true
			}
		case *body:
			bdy.mu.Lock()
			switch {
			case bdy.closed:
				if !bdy.sawEOF {
					// Body was closed in handler with non-EOF error.
					w.closeAfterReply = true
				}
			case bdy.unreadDataSizeLocked() >= maxPostHandlerReadBytes:
				tooBig = true
			default:
				discard = true
			}
			bdy.mu.Unlock()
		default:
			discard = true
		}

		if discard {
			**_, err := io.CopyN(ioutil.Discard, w.reqBody, maxPostHandlerReadBytes+1)**
			switch err {
			case nil:
				// There must be even more data left over.
				tooBig = true
			case ErrBodyReadAfterClose:
				// Body was already consumed and closed.
			case io.EOF:
				// The remaining body was just consumed, close it.
				err = w.reqBody.Close()
				if err != nil {
					w.closeAfterReply = true
				}
			default:
				// Some other kind of error occurred, like a read timeout, or
				// corrupt chunked encoding. In any case, whatever remains
				// on the wire must not be parsed as another HTTP request.
				w.closeAfterReply = true
			}
		}
.......
}

io.CopyN(ioutil.Discard, w.reqBody, maxPostHandlerReadBytes+1) this method will cost 8s to read 256k data

[winworm]

this is the debug result

chunkedwriterclose:8.276652351s
abort inRead is false
abortPendingRead:5.411µs
doEarlyClose

[agnivade]

Ok, so if I understand you correctly, you want to sleep for 20ms after every write, but still you want to get the result immediately. I will let @bradfitz decide if he wants to reopen this.