net/http: first byte of second request in hijack mode is lost

[jzwlqx]

Please answer these questions before submitting your issue. Thanks!

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

go version go1.11 darwin/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="/Users/jjz/Library/Caches/go-build"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOOS="darwin"
GOPATH="/Users/jjz/go"
GOPROXY=""
GORACE=""
GOROOT="/opt/go"
GOTMPDIR=""
GOTOOLDIR="/opt/go/pkg/tool/darwin_amd64"
GCCGO="gccgo"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD=""
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 -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/x2/t219h_ks1wl4gjwnz82xc17h0000gn/T/go-build513787949=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

Hijack client http request to backend server in go http server. If the underlay connection is reused which means more than one http request is send over the connection, when first request has body size >0, first byte of the second request will be eat.

To reproduce this issue, I wrote a simple testcase. Client send requests to a transparent proxy who forward requests to backend server in hijack mode. The backend server is a simple echo server, response request method and body to its client. Below are the codes:

Proxy & Server

package main

import (
	"net/http"
	"net"
	"sync"
	"io"
	"fmt"
	"bytes"
)

func echo(w http.ResponseWriter, r *http.Request) {
	w.WriteHeader(200)
	var buf bytes.Buffer
	io.Copy(&buf, r.Body)
	resp := fmt.Sprintf("method: %s, body: %s", r.Method, buf.String())
	w.Write([]byte(resp))
}

type Proxy struct {
	Backend string
}

func (p *Proxy) ServeHTTP(w http.ResponseWriter, r *http.Request) {
	fmt.Printf("Receive a request from %v\n", r.RemoteAddr)
	hj, ok := w.(http.Hijacker)
	if !ok {
		http.Error(w, "webserver doesn't support hijacking", http.StatusInternalServerError)
		return
	}

	backendConn, err := net.Dial("tcp", p.Backend)
	if err != nil {
		fmt.Printf("err: %v\n", err)
		return
	}
	defer backendConn.Close()

	clientConn, bufrw, err := hj.Hijack()
	if err != nil {
		return
	}

	defer clientConn.Close()

	if err := r.Write(backendConn); err != nil {
		return
	}

	var wg = sync.WaitGroup{}
	wg.Add(2)
	copy := func(dst io.Writer, src io.Reader) {
		io.Copy(dst, src)
		if conn, ok := dst.(interface {
			CloseWrite() error
		}); ok {
			conn.CloseWrite()
		}
		wg.Done()
	}

	bufferedReader := io.LimitReader(bufrw, int64(bufrw.Reader.Buffered()))
	mr := io.MultiReader(bufferedReader, clientConn)

	go copy(clientConn, backendConn)
	go copy(backendConn, mr)
	wg.Wait()
}

func main() {
	go http.ListenAndServe(":8081", http.HandlerFunc(echo))

	p := &Proxy{Backend: "localhost:8081"}
	http.ListenAndServe(":8080", p)
}

Client:

package main

import (
	"net/http"
	"bytes"
	"io"
	"os"
	"fmt"
)

func req(client *http.Client, msg string) {
	body := bytes.NewBufferString(msg)
	r, err := http.NewRequest("POST", "http://localhost:8080/", body)
	if err != nil {
		panic(err)
	}
	resp, err := client.Do(r)
	if err != nil {
		panic(err)
	}
	defer resp.Body.Close()
	if _, err := io.Copy(os.Stdout, resp.Body); err != nil {
		panic(err)
	}
}

func main() {
	c := &http.Client{}
	fmt.Println("Send 'Hello'")
	req(c, "Hello")
	fmt.Println()

	fmt.Println("Send 'World'")
	req(c, "World")
}

1. Run the server in terminal: go run server.go
2. Open another terminal, run go run client.go

Output show that the letter P (of word POST) POST is lost.

What did you expect to see?

go run client.go
Send 'Hello'
method: POST, body: Hello
Send 'World'
method: POST, body: World

What did you see instead?

go run client.go
Send 'Hello'
method: POST, body: Hello
Send 'World'
method: OST, body: World

[gopherbot]

Change https://golang.org/cl/132479 mentions this issue: net/http: don't run backgroundRead if connection was hijacked Fixes #27408

[FiloSottile]

Is this a regression in 1.11?

/cc @bradfitz

[jzwlqx]

@FiloSottile I tested go 1.8, 1.9, 1.10, 1.11 on MacOS and Linux， all of them have this issue。

https://go-review.googlesource.com/c/go/+/132479 is a fix.

[odeke-em]

@jzwlqx I have distilled your repro into an end-to-end test that you can then use in your fixing CL

package main_test

import (
	"bytes"
	"fmt"
	"io"
	"io/ioutil"
	"net"
	"net/http"
	"net/http/httptest"
	"net/url"
	"sync"
	"testing"
)

func TestIssue(t *testing.T) {
	backend := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		slurp, _ := ioutil.ReadAll(r.Body)
		_ = r.Body.Close()
		fmt.Fprintf(w, "method: %s, body: %s\n", r.Method, slurp)
	}))
	defer backend.Close()
	bu, _ := url.Parse(backend.URL)

	proxy := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		hj, ok := w.(http.Hijacker)
		if !ok {
			http.Error(w, "webserver doesn't support hijacking", http.StatusInternalServerError)
			return
		}

		bc, err := net.Dial("tcp", bu.Host)
		if err != nil {
			http.Error(w, err.Error(), http.StatusInternalServerError)
			return
		}
		defer bc.Close()

		cc, bw, err := hj.Hijack()
		if err != nil {
			http.Error(w, err.Error(), http.StatusInternalServerError)
			return
		}
		defer cc.Close()

                if err := r.Write(bc); err != nil {
			http.Error(w, err.Error(), http.StatusInternalServerError)
			return
		}

		var wg sync.WaitGroup
		wg.Add(2)
		cp := func(dst io.Writer, src io.Reader) {
			_, _ = io.Copy(dst, src)
			if conn, ok := dst.(interface {
				CloseWrite() error
			}); ok {
				conn.CloseWrite()
			}
			wg.Done()
		}

		lr := io.LimitReader(bw, int64(bw.Reader.Buffered()))
		mr := io.MultiReader(lr, cc)

		go cp(cc, bc)
		go cp(bc, mr)
		wg.Wait()
	}))
	defer proxy.Close()

	// And now for the client

	gotLog := new(bytes.Buffer)
	clientReq := func(msg string) error {
		body := bytes.NewBufferString(msg)
		req, err := http.NewRequest("POST", proxy.URL, body)
		if err != nil {
			return err
		}
		resp, err := proxy.Client().Do(req)
		if err != nil {
			return err
		}
		_, err = io.Copy(gotLog, resp.Body)
		resp.Body.Close()
		return err
	}

	payloads := []string{"Hello", "World"}
	for _, payload := range payloads {
		if err := clientReq(payload); err != nil {
			t.Fatalf("Payload %q ==> %v", payload, err)
		}
	}
        wantLog := "method: POST, body: Hello\nmethod: POST, body: World\n"
	if g, w := gotLog.String(), wantLog; g != w {
		t.Fatalf("\nGot =%q\nWant=%q", g, w)
	}
}

However, the test passes undeterministically, for example with:

• a count of 5, it passes 2/5 times

$ go test -count=5
--- FAIL: TestIssue (0.00s)
    issue_test.go:98: 
        Got ="method: POST, body: Hello\nmethod: OST, body: World\n"
        Want="method: POST, body: Hello\nmethod: POST, body: World\n"
--- FAIL: TestIssue (0.00s)
    issue_test.go:98: 
        Got ="method: POST, body: Hello\nmethod: OST, body: World\n"
        Want="method: POST, body: Hello\nmethod: POST, body: World\n"
--- FAIL: TestIssue (0.00s)
    issue_test.go:98: 
        Got ="method: POST, body: Hello\nmethod: OST, body: World\n"
        Want="method: POST, body: Hello\nmethod: POST, body: World\n"

• a count of 10, it passes 3/10 times

$ go test -count=10
--- FAIL: TestIssue (0.00s)
    issue_test.go:98: 
        Got ="method: POST, body: Hello\nmethod: OST, body: World\n"
        Want="method: POST, body: Hello\nmethod: POST, body: World\n"
--- FAIL: TestIssue (0.00s)
    issue_test.go:98: 
        Got ="method: POST, body: Hello\nmethod: OST, body: World\n"
        Want="method: POST, body: Hello\nmethod: POST, body: World\n"
--- FAIL: TestIssue (0.00s)
    issue_test.go:98: 
        Got ="method: POST, body: Hello\nmethod: OST, body: World\n"
        Want="method: POST, body: Hello\nmethod: POST, body: World\n"
--- FAIL: TestIssue (0.00s)
    issue_test.go:98: 
        Got ="method: POST, body: Hello\nmethod: OST, body: World\n"
        Want="method: POST, body: Hello\nmethod: POST, body: World\n"
--- FAIL: TestIssue (0.00s)
    issue_test.go:98: 
        Got ="method: POST, body: Hello\nmethod: OST, body: World\n"
        Want="method: POST, body: Hello\nmethod: POST, body: World\n"
--- FAIL: TestIssue (0.00s)
    issue_test.go:98: 
        Got ="method: POST, body: Hello\nmethod: OST, body: World\n"
        Want="method: POST, body: Hello\nmethod: POST, body: World\n"
--- FAIL: TestIssue (0.00s)
    issue_test.go:98: 
        Got ="method: POST, body: Hello\nmethod: OST, body: World\n"
        Want="method: POST, body: Hello\nmethod: POST, body: World\n"
FAIL
exit status 1
FAIL	_/Users/emmanuelodeke/Desktop/openSrc/bugs/golang/27408	0.022s

[jzwlqx]

@odeke-em thanks a lot for your test, I will add it to the fixing CL.

Did you try run go test with setting GOROOT to the newly built go?

Result in my environment with patched go:

% ls
main_test.go
% env GOROOT=/tmp/go-master /tmp/go-master/bin/go test -count=20
PASS
ok _/tmp/go-master/t 0.040s

[odeke-em]

@jzwlqx I ran the test before applying your patch, but as I showed, at times it worked alright and didn't fail 100% of the time. Perhaps that could be due to connection reuse? Anyways you've submitted the patch. Unfortunately your commit message edits aren't reflected on Gerrit so please try to edit them on the PR directly or on Gerrit itself.

[gopherbot]

Change https://golang.org/cl/133416 mentions this issue: net/http: don't run backgroundRead if connection was hijacked

[jzwlqx]

@odeke-em That is because there are two goroutines try to read the same tcp connection at the same time. One is connRead.backgroundRead in net/http/server.go and the other is handler of proxy in the testcase above. When tcp data arrives, only one goroutine can get it and return from net.Conn.Read。Which goroutine would get the tcp input is undetermined. If backgroundRead read it, one byte lost, If io.Copy in handler get it, everything goes OK.

In the above testcase, body size is too small, if we construct a big enough body, it's inevitable that backgroundRead would get one byte at sometime and one byte lost.