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: first byte of second request in hijack mode is lost #27408

Open
jzwlqx opened this issue Aug 31, 2018 · 8 comments
Open

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

jzwlqx opened this issue Aug 31, 2018 · 8 comments
Labels
NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone

Comments

@jzwlqx
Copy link

jzwlqx commented Aug 31, 2018

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

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

@FiloSottile FiloSottile changed the title first byte of second request in hijack mode is lost net/http: first byte of second request in hijack mode is lost Aug 31, 2018
@FiloSottile FiloSottile added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Aug 31, 2018
@FiloSottile FiloSottile added this to the Go1.12 milestone Aug 31, 2018
@FiloSottile
Copy link
Contributor

Is this a regression in 1.11?

/cc @bradfitz

@jzwlqx
Copy link
Author

jzwlqx commented Sep 1, 2018

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

odeke-em commented Sep 3, 2018

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

jzwlqx commented Sep 3, 2018

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

odeke-em commented Sep 5, 2018

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

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

@jzwlqx
Copy link
Author

jzwlqx commented Sep 5, 2018

@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.

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

6 participants