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: server waits for maxPostHandlerReadBytes of a chunked request before returning error #25475

Closed
winworm opened this issue May 21, 2018 · 11 comments
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone

Comments

@winworm
Copy link

winworm commented May 21, 2018

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

When the server validator fails,

What is this server validator ? Why will it fail ?

Can you please upload a complete and independent code sample ?

@agnivade agnivade added the WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. label May 21, 2018
@bcmills bcmills changed the title Go Server waiting for reading maxPostHandlerReadBytes to flush the responce to client for continue sending data net/http: server waits for maxPostHandlerReadBytes of a chunked request before returning error May 21, 2018
@bcmills bcmills added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label May 21, 2018
@bcmills
Copy link
Contributor

bcmills commented May 21, 2018

(CC: @bradfitz, but awaiting more detail)

@bradfitz
Copy link
Contributor

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.

@bradfitz bradfitz added this to the Unplanned milestone May 21, 2018
@winworm
Copy link
Author

winworm commented May 22, 2018

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

@everfighter
Copy link

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

@agnivade
Copy link
Contributor

agnivade commented May 23, 2018

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

@agnivade agnivade removed the WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. label May 23, 2018
@agnivade
Copy link
Contributor

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

winworm commented May 24, 2018

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

winworm commented May 24, 2018

this is the debug result

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

@agnivade
Copy link
Contributor

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.

@golang golang locked and limited conversation to collaborators May 24, 2019
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
FrozenDueToAge 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

6 participants