net/http: background read can lose a byte

[bmizerany]

Please answer these questions before submitting your issue. Thanks!

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

go version devel +41908a5 Thu Dec 1 02:54:21 2016 +0000 darwin/amd64

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

GOARCH="amd64"
GOBIN=""
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOOS="darwin"
GOPATH="/Users/bmizerany"
GORACE=""
GOROOT="/usr/local/go"
GOTOOLDIR="/usr/local/go/pkg/tool/darwin_amd64"
GCCGO="gccgo"
CC="clang"
GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/dx/jcs03lw901vc05cjjqyjf8y00000gn/T/go-build129210763=/tmp/go-build -gno-record-gcc-switches -fno-common"
CXX="clang++"
CGO_ENABLED="1"
PKG_CONFIG="pkg-config"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"

What did you do?

I ran this benchmark:

func BenchmarkBug(b *testing.B) {
	hts := httptest.NewServer(http.HandlerFunc(http.NotFound))
	defer hts.Close()

	cn, err := net.Dial("tcp", hts.Listener.Addr().String())
	if err != nil {
		panic(err)
	}
	defer func() {
		println("CLOSING")
		cn.Close() // <-- getting called too early?
	}()

	go io.Copy(ioutil.Discard, cn) // discard responses

	reqBytes := []byte("GET / HTTP/1.1\r\nHost: e.com\r\n\r\n")

	b.RunParallel(func(pb *testing.PB) {
		for pb.Next() {
			_, err := cn.Write(reqBytes)
			if err != nil {
				panic(err)
			}
		}
		println("DONE")
	})
}

What did you expect to see?

PASS

What did you see instead?

$ go test -run=none -bench=BenchmarkBug
DONE
DONE
DONE
DONE
CLOSING
BenchmarkBug-4   	DONE
DONE
DONE
DONE
CLOSING
panic: write tcp 127.0.0.1:55752->127.0.0.1:55751: write: broken pipe

goroutine 66 [running]:
backplane2/server.BenchmarkBug.func2(0xc42000c2e0)
	/Users/bmizerany/src/bug/bench_test.go:261 +0xb7 // <--- The panic
testing.(*B).RunParallel.func1(0xc42011e0f0, 0xc42011e0e0, 0xc42011e0d8, 0xc4200b0000, 0xc420010810)
	/usr/local/go/src/testing/benchmark.go:606 +0xc2
created by testing.(*B).RunParallel
	/usr/local/go/src/testing/benchmark.go:607 +0x1af
FAIL	bug 2.385s

[bmizerany]

I just tried on tip go version devel +867dcb5 Fri Jan 6 01:58:00 2017 +0000 darwin/amd64 and got the same result.

[ianlancetaylor]

It's not a problem in the testing package. The net/http Server is seeing a bad request and closing the connection. You have a bunch of different goroutines, running in parallel, writing to the same network connection. As the socket buffer fills up, nothing guarantees that those writes are atomic. When I run an strace, I see that eventually a short write occurs. The Go code calls write again with the remaining bytes, but in the meantime another thread does a write to the same socket. The HTTP server sees a mangled request, returns a "400 Bad Request" error, and closes the connection. The next write fails with a broken pipe, and your code panics.

I don't think there is anything we can fix here, so closing.

[bmizerany]

Wow. My bad. Thank you.

…

On Fri, Jan 6, 2017 at 7:05 AM Ian Lance Taylor ***@***.***> wrote: Closed #18535 <#18535>. — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub <#18535 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AAAALr-s10JPXw5X2a2kY6WJgxGFSkhAks5rPlgZgaJpZM4Lcg43> .

[bmizerany]

I've modified the code to not share a connection but rather each running goroutine gets their own. I'm still seeing the issue and have dug around in dtruss looking for clues but I don't see any malformed requests expect when I copy the responses to stderr I do see a 400 response after many valid responses. I may be doing something very silly again but I can't seem to find it. Any help is appreciated.

Update bench:

package server

import (
	"io"
	"io/ioutil"
	"net"
	"net/http"
	"net/http/httptest"
	"testing"
)

func BenchmarkBug(b *testing.B) {
	hts := httptest.NewServer(http.HandlerFunc(http.NotFound))
	defer hts.Close()

	reqBytes := []byte("GET / HTTP/1.1\r\nHost: e.com\r\n\r\n")

	b.RunParallel(func(pb *testing.PB) {
		cn, err := net.Dial("tcp", hts.Listener.Addr().String())
		if err != nil {
			panic(err)
		}
		defer cn.Close()

		go io.Copy(ioutil.Discard, cn)

		for pb.Next() {
			_, err := cn.Write(reqBytes)
			if err != nil {
				panic(err)
			}
		}
	})
}

[ianlancetaylor]

CC @bradfitz

This is a real bug. The net/http server is dropping an occasional byte.

If I add these lines to connReader.startBackgroundRead

	if cr.hasByte {
		panic("startBackgroundRead when already have byte")
	}

your program triggers the panic. Doing a background read when we already have a byte from an earlier background read is causing one of the bytes to be lost.

I don't understand exactly what triggers the condition. It has something to do with a full TCP buffer containing many GET requests and ending in the middle of a line.

I hope that Brad can take it from here.

[bradfitz]

I guess I now have weekend plans.

[ianlancetaylor]

Your weekend is open again: https://golang.org/cl/34920.

[gopherbot]

CL https://golang.org/cl/34920 mentions this issue.

[bmizerany]

Killer. Thank you @ianlancetaylor.