Skip to content

net/http/httputil: ReverseProxy read error during body copy use of closed network connection #40747

Closed
@ccdeville

Description

@ccdeville

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

$ go version
go version go1.14.2 windows/amd64

Does this issue reproduce with the latest release?

yes

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

go env Output
$ go env
set GO111MODULE=
set GOARCH=amd64
set GOBIN=
set GOCACHE=C:\Users\Administrator\AppData\Local\go-build
set GOENV=C:\Users\Administrator\AppData\Roaming\go\env
set GOEXE=.exe
set GOFLAGS=
set GOHOSTARCH=amd64
set GOHOSTOS=windows
set GOINSECURE=
set GONOPROXY=
set GONOSUMDB=
set GOOS=windows
set GOPATH=D:\wxgo
set GOPRIVATE=
set GOPROXY=https://goproxy.io,direct
set GOROOT=D:\Go
set GOSUMDB=sum.golang.org
set GOTMPDIR=
set GOTOOLDIR=D:\Go\pkg\tool\windows_amd64
set GCCGO=gccgo
set AR=ar
set CC=gcc
set CXX=g++
set CGO_ENABLED=1
set GOMOD=
set CGO_CFLAGS=-g -O2
set CGO_CPPFLAGS=
set CGO_CXXFLAGS=-g -O2
set CGO_FFLAGS=-g -O2
set CGO_LDFLAGS=-g -O2
set PKG_CONFIG=pkg-config
set GOGCCFLAGS=-m64 -mthreads -fno-caret-diagnostics -Qunused-arguments -fmessag
e-length=0 -fdebug-prefix-map=C:\Users\ADMINI~1\AppData\Local\Temp\go-build74128
8550=/tmp/go-build -gno-record-gcc-switches

What did you do?

  • I created a proxy and a restfulapi server
  • I used postman made many post requests with body request to server through the proxy(proxy and server run in the same vm,server runed used docker,They use docker0 to connect),and server response body is larger than 4K
  • all requests use http/1.1
  • OS:Centos7.4

What did you expect to see?

post request sucessed and there is only one persistent connection

What did you see instead?

the following log appears in proxy .

httputil: ReverseProxy read error during body copy: read tcp 172.17.0.1:39810->172.17.0.2:8082: use of closed network connection

many TIME_WAIT conntecions appears .
Everything was ok in any of the the following scenarios:

  • Post request without body
  • GET request with same response
  • Response body less than 4K
  • Do not use Keep-Alive
  • Server response not write "Content-Length" in header
  • Use NGINX instead of my proxy
  • Server runed in a vm
PROXY Output
package main

import (
"flag"
"net/http"
"net/http/httputil"
"net/url"
"time"
)

var burl = flag.String("u", "", "backend address")

func buildProxy(target *url.URL) *httputil.ReverseProxy {
flushInterval := time.Duration(100 * time.Millisecond)
passHost := true
passHostHeader := &passHost
targetQuery := target.RawQuery
proxy := &httputil.ReverseProxy{
Director: func(req *http.Request) {
req.URL.Path = target.Path
req.URL.Host = target.Host
req.URL.Scheme = target.Scheme

		req.URL.RawPath = target.RawPath
		if targetQuery == "" || req.URL.RawQuery == "" {
			req.URL.RawQuery = targetQuery + req.URL.RawQuery
		} else {
			req.URL.RawQuery = targetQuery + "&" + req.URL.RawQuery
		}
		req.RequestURI = ""
		req.Proto = "HTTP/1.1"
		req.ProtoMajor = 1
		req.ProtoMinor = 1
		if passHostHeader != nil && !*passHostHeader {
			req.Host = req.URL.Host
		}
	},
	Transport:     http.DefaultTransport,
	FlushInterval: flushInterval,
}
return proxy

}

func handler(p *httputil.ReverseProxy) func(http.ResponseWriter, *http.Request) {
return func(w http.ResponseWriter, r *http.Request) {

	p.ServeHTTP(w, r)
}

}
func main() {
flag.Parse()
remote, err := url.ParseRequestURI("http://" + *burl)
if err != nil {
panic(err)
}

proxy := buildProxy(remote)
http.HandleFunc("/", handler(proxy))
err = http.ListenAndServe(":8081", nil)
if err != nil {
	panic(err)
}

}

SERVER Output
package main

import (
"fmt"
"strconv"
"github.com/gin-gonic/gin"
)

type myJson struct {
Name string json:"name"
}

func createBigString(name string) string {

var bs string
for i := 1; i <= 500; i++ {
	bs += name + "abcdefghij"

}

return bs

}
func main() {
gin.SetMode(gin.ReleaseMode)
router := gin.Default()

router.POST("/test/post", func(c *gin.Context) {
	var json myJson
	c.ShouldBindJSON(&json)
	myName := createBigString(json.Name)
	lenBody := len(myName) + 11
	fmt.Println(lenBody)
	c.Header("Content-Length", strconv.Itoa(lenBody))
	c.JSON(200, gin.H{"name": myName})
})
router.Run(":8082")

}

Activity

changed the title [-]ReverseProxy read error during body copy[/-] [+]ReverseProxy read error during body copy use of closed network connection[/+] on Aug 13, 2020
changed the title [-]ReverseProxy read error during body copy use of closed network connection[/-] [+]net/http/httputil:ReverseProxy read error during body copy use of closed network connection[/+] on Aug 13, 2020
changed the title [-]net/http/httputil:ReverseProxy read error during body copy use of closed network connection[/-] [+]net/http/httputil: ReverseProxy read error during body copy use of closed network connection[/+] on Aug 13, 2020
dmitshur

dmitshur commented on Aug 17, 2020

@dmitshur
Member

/cc @bradfitz per owners.

added
NeedsInvestigationSomeone must examine and confirm this is a valid issue and not a duplicate of an existing one.
on Aug 17, 2020
added this to the Backlog milestone on Aug 17, 2020
coolaj86

coolaj86 commented on Nov 13, 2020

@coolaj86

I've got something that I think could be related to this - also on Windows, but I'm getting a panic as well:

2020/11/12 15:22:28 httputil: ReverseProxy read error during body copy: read tcp 127.0.0.1:49351->127.0.0.1:8090: wsarecv: An established connection was aborted by the software in your host machine.
panic: runtime error: invalid memory address or nil pointer dereference
[signal 0xc0000005 code=0x0 addr=0x18 pc=0x667335]
goroutine 147 [running]:
bufio.(*Reader).Read(0xc00018e180, 0xc0002e4000, 0x2000, 0x2000, 0x2000, 0xc0002e4000, 0xc000182f20)
    E:/Dev/Go/src/bufio/bufio.go:212 +0x125
io.(*LimitedReader).Read(0xc000182ec0, 0xc0002e4000, 0x2000, 0x2000, 0xc00008e140, 0x10, 0xc000307be8)
    E:/Dev/Go/src/io/io.go:451 +0x6a
net/http.(*body).readLocked(0xc0000e0cc0, 0xc0002e4000, 0x2000, 0x2000, 0x2000, 0xc0002e4000, 0xc0001ac980)
    E:/Dev/Go/src/net/http/transfer.go:847 +0x66
net/http.bodyLocked.Read(0xc0000e0cc0, 0xc0002e4000, 0x2000, 0x2000, 0x0, 0x0, 0x0)
    E:/Dev/Go/src/net/http/transfer.go:1046 +0x85
io.(*LimitedReader).Read(0xc0001ac960, 0xc0002e4000, 0x2000, 0x2000, 0xc000085a30, 0x409d72, 0xc000008000)
    E:/Dev/Go/src/io/io.go:451 +0x6a
io/ioutil.devNull.ReadFrom(0x0, 0xae2760, 0xc0001ac960, 0x985880, 0x1, 0x273fbf68)
    E:/Dev/Go/src/io/ioutil/ioutil.go:144 +0x99
io.copyBuffer(0xae3400, 0xed2d98, 0xae2760, 0xc0001ac960, 0x0, 0x0, 0x0, 0x5, 0x1, 0xc0001ff740)
    E:/Dev/Go/src/io/io.go:391 +0x303
io.Copy(...)
    E:/Dev/Go/src/io/io.go:364
io.CopyN(0xae3400, 0xed2d98, 0xae34e0, 0xc0000e0cc0, 0x40000, 0xc0000c8a50, 0x0, 0xc000022ac0)
    E:/Dev/Go/src/io/io.go:340 +0xa1
net/http.(*body).Close(0xc0000e0cc0, 0x0, 0x0)
    E:/Dev/Go/src/net/http/transfer.go:999 +0x14a
net/http.(*Request).closeBody(...)
    E:/Dev/Go/src/net/http/request.go:1391
net/http.(*persistConn).writeLoop(0xc0000647e0)
    E:/Dev/Go/src/net/http/transport.go:2296 +0x364
created by net/http.(*Transport).dialConn
    E:/Dev/Go/src/net/http/transport.go:1648 +0xc82

This happened after a local application that communicates with this process had been running for a few weeks successfully.

davecheney

davecheney commented on Nov 13, 2020

@davecheney
Contributor

This looks like memory corruption. Have you tried running your program under the race detector? See https://blog.golang.org/race-detector .

markusthoemmes

markusthoemmes commented on Nov 25, 2020

@markusthoemmes

I'm hitting the very same symptoms on Golang 1.15.5.

I also whipped up a quick reproducer that reliably fails on my machine:

`go env` output

GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/mthoemme/.cache/go-build"
GOENV="/home/mthoemme/.config/go/env"
GOEXE=""
GOFLAGS="-mod=vendor"
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GOMODCACHE="/home/mthoemme/go/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/home/mthoemme/go"
GOPRIVATE=""
GOPROXY="direct"
GOROOT="/usr/lib/golang"
GOSUMDB="off"
GOTMPDIR=""
GOTOOLDIR="/usr/lib/golang/pkg/tool/linux_amd64"
GCCGO="gccgo"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD="/home/mthoemme/dev/debugging/serving-EOF/queue-proxy-use-of-closed-network-connection-error/go.mod"
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-build009849173=/tmp/go-build -gno-record-gcc-switches"

Reproducer

package main

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

const (
	bodySize          = 32 * 1024
	parallelism       = 32
	disableKeepAlives = false
)

func TestProxyEcho(t *testing.T) {
	// The server responding with the sent body.
	echoServer := httptest.NewServer(http.HandlerFunc(
		func(w http.ResponseWriter, req *http.Request) {
			body, err := ioutil.ReadAll(req.Body)
			if err != nil {
				log.Printf("error reading body: %v", err)
				http.Error(w, fmt.Sprintf("error reading body: %v", err), http.StatusInternalServerError)
				return
			}

			if _, err := w.Write(body); err != nil {
				log.Printf("error writing body: %v", err)
			}
		},
	))
	defer echoServer.Close()

	// The server proxying requests to the echo server.
	echoURL, err := url.Parse(echoServer.URL)
	if err != nil {
		t.Fatalf("Failed to parse echo URL: %v", err)
	}
	proxy := httputil.NewSingleHostReverseProxy(echoURL)
	proxyServer := httptest.NewServer(proxy)
	defer proxyServer.Close()

	transport := http.DefaultTransport.(*http.Transport).Clone()
	transport.DisableKeepAlives = disableKeepAlives
	c := &http.Client{
		Transport: transport,
	}

	body := make([]byte, bodySize)
	for i := 0; i < cap(body); i++ {
		body[i] = 42
	}

	var wg sync.WaitGroup
	wg.Add(parallelism)
	for i := 0; i < parallelism; i++ {
		go func(i int) {
			defer wg.Done()

			for i := 0; i < 1000; i++ {
				if err := send(c, proxyServer.URL, body); err != nil {
					t.Errorf("error during request: %v", err)
				}
			}
		}(i)
	}

	wg.Wait()
}

func send(client *http.Client, url string, body []byte) error {
	r := bytes.NewBuffer(body)
	req, err := http.NewRequest("POST", url, r)
	if err != nil {
		return fmt.Errorf("failed to create request: %w", err)
	}

	resp, err := client.Do(req)
	if err != nil {
		return fmt.Errorf("failed to execute request: %w", err)
	}
	defer resp.Body.Close()

	rec, err := ioutil.ReadAll(resp.Body)
	if err != nil {
		return fmt.Errorf("failed to read body: %w", err)
	}

	if resp.StatusCode != http.StatusOK {
		return fmt.Errorf("unexpected status code: %d", resp.StatusCode)
	}

	if len(rec) != len(body) {
		return fmt.Errorf("unexpected body length: %d", len(rec))
	}

	return nil
}

markusthoemmes

markusthoemmes commented on Dec 7, 2020

@markusthoemmes

Any chance we can get some guidance/help investigating this? @bradfitz @rsc @empijei (per OWNERS)

empijei

empijei commented on Dec 16, 2020

@empijei
Contributor

cc/ @FiloSottile this looks like #34902, which you worked on. WDYT?

This also looks a lot like #15527 but I didn't find the race at a first glance. Running the code suggested by @markusthoemmes a few times reliably repros the issue, but even if ran with -race the detector does not pick up the race so it's not a trivial one.

The offending call seems to be

err = p.copyResponse(rw, res.Body, p.flushInterval(res))

which calls

_, err := p.copyBuffer(dst, src, buf)

which encounters this error here:

nr, rerr := src.Read(buf)

If we look at the first snippet, data is copied from res.Body to rw.

My best guess here is that while we are reading from res.Body this transport.RoundTrip call might still be writing to the outgoing request.

This could be caused by a persistent connection doing some work in the background, but it would require some more in-depth analysis to validate.

duglin

duglin commented on Dec 17, 2020

@duglin

Not 100% sure it's related but it does appear the reverseproxy has issues with raw tcp stuff - see this: knative/serving#6146 (comment)

25 remaining items

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    FrozenDueToAgeNeedsInvestigationSomeone must examine and confirm this is a valid issue and not a duplicate of an existing one.

    Type

    No type

    Projects

    No projects

    Relationships

    None yet

      Development

      No branches or pull requests

        Participants

        @davecheney@dprotaso@neild@coolaj86@stephens2424

        Issue actions

          net/http/httputil: ReverseProxy read error during body copy use of closed network connection · Issue #40747 · golang/go