net/http: Goroutine leak in http client/transport #9092

gopherbot · 2014-11-12T04:32:07Z

by ronee.9:

Go version 1.3 (checked latest 1.3.3, it seems no changes at http client/transport)

I write a server to send http request to other servers, and found out the go routine
keep increases, and there are thousands of go routines like:

goroutine 1803 [chan receive, 117 minutes]:
net/http.(*persistConn).readLoop(0xc208477080)
    /usr/local/go/src/pkg/net/http/transport.go:798 +0x30b
created by net/http.(*Transport).dialConn
    /usr/local/go/src/pkg/net/http/transport.go:600 +0x93f

Not sure why it blocks here.
I am sending the http request like this:

    content := "anystring"
    buf := bytes.NewBufferString(content)
    req, err = http.NewRequest("POST", "anyurl", buf)
    if err != nil {
        return
    }
    req.Header.Add("Content-type", "application/x-www-form-urlencoded")
    return

gopherbot · 2014-11-12T04:36:32Z

Comment 1 by ronee.9:

My httpclient is like this
func NewTimeoutClient(connectTimeout time.Duration, responseHeaderTimeout time.Duration)
*http.Client {
    return &http.Client{
        Transport: &http.Transport{
            Dial: TimeoutDialer(connectTimeout),
            ResponseHeaderTimeout: responseHeaderTimeout,
        },
        Timeout : HTTP_TIMEOUT * time.Second,
    }
}

ianlancetaylor · 2014-11-12T05:11:01Z

Comment 2:

Labels changed: added repo-main, release-go1.5.

bradfitz · 2014-11-12T15:15:01Z

Comment 3:

You need to close your Response.Body io.ReadClosers. And don't create more than one
transport. Or if you want its cached idle connections to go away, call
CloseIdleConnections on it.

Status changed to WorkingAsIntended.

gopherbot · 2014-12-03T05:12:17Z

Comment 4 by ronee.9:

Thanks bradfitz's replay and sorry for late feedback.
I have closed the Response.Body by call defer resp.Body.Close().
What do you mean by do not create more than one transport? I create the http client with
this code, and it has only one transport:
func NewTimeoutClient(connectTimeout time.Duration, responseHeaderTimeout time.Duration)
*http.Client {
    return &http.Client{
        Transport: &http.Transport{
            Dial: TimeoutDialer(connectTimeout),
            ResponseHeaderTimeout: responseHeaderTimeout,
        },
        Timeout : HTTP_TIMEOUT * time.Second,
    }
}
I also checked the number of tcp connections, it is OK. i.e. the tcp connection is
reused successfully and not increasing like the go routines.
I traced the code, the block place seems wired at transport.go
798 rc := <-pc.reqch

bradfitz · 2014-12-03T05:25:09Z

Comment 5:

Do you call your NewTimeoutClient more than once? That's what I meant by not making more
than one Transport if you're not going to call CloseIdleConnections.

gopherbot · 2014-12-03T05:48:34Z

Comment 6 by ronee.9:

Yes. I called it only once.

bradfitz · 2014-12-03T05:49:45Z

Comment 7:

Please post a complete but minimal reproduction program.

gopherbot · 2014-12-03T05:56:18Z

Comment 8 by ronee.9:

OK, i will try to do it.

gopherbot · 2014-12-03T06:27:23Z

Comment 9 by ronee.9:

Following is the code, it sends 3 http request and it generate three chan receive blocks
as the profile shown after the code
package main
import (
    "fmt"
    "net/http"
    //"encoding/xml"
    "bytes"
    "io/ioutil"
    //"log"
    "net"
    "net/http/httputil"
    _ "net/http/pprof"
    "strconv"
    "time"
)
const (
    CONNECTION_TIMEOUT      = 20
    RESPONSE_HEADER_TIMEOUT = 60
    HTTP_TIMEOUT            = 90
)
func TimeoutDialer(connectTimeout time.Duration) func(net, addr string) (net.Conn,
error) {
    return func(network, address string) (net.Conn, error) {
        conn, err := net.DialTimeout(network, address, connectTimeout)
        return conn, err
    }
}
func NewDefaultTimeoutClient() *http.Client {
    return NewTimeoutClient(CONNECTION_TIMEOUT*time.Second, RESPONSE_HEADER_TIMEOUT*time.Second)
}
func NewTimeoutClient(connectTimeout time.Duration, responseHeaderTimeout time.Duration)
*http.Client {
    return &http.Client{
        Transport: &http.Transport{
            Dial: TimeoutDialer(connectTimeout),
            ResponseHeaderTimeout: responseHeaderTimeout,
        },
        Timeout: HTTP_TIMEOUT * time.Second,
    }
}
func main() {
    go http.ListenAndServe(":6168", nil) //profiling
    client := NewDefaultTimeoutClient()
    for i := 0; i < 3; i++ {
        fmt.Println("Test ", i)
        content := fmt.Sprintf("api_key=%s&api_secret=%s&from=%s&to=%s&text=test%d&status-report-req=1",
            "xxx", "xxx", "xxx", "1234", i)
        buf := bytes.NewBufferString(content)
        req, err := http.NewRequest("POST", "http://xxx", buf)
        if err == nil {
            req.Header.Add("Content-type", "application/x-www-form-urlencoded")
            req.Header.Add("Content-Length", strconv.Itoa(len(content)))
            output, _ := httputil.DumpRequestOut(req, true)
            fmt.Println("DEBUG: ", string(output))
            resp, err := client.Do(req)
            if err == nil {
                respStr, err := ioutil.ReadAll(resp.Body)
                if err == nil {
                    fmt.Println("resp: ", string(respStr))
                } else {
                    fmt.Println("ERROR: ", err)
                }
            } else {
                fmt.Println("ERROR: ", err)
            }
            resp.Body.Close()
        } else {
            fmt.Println("ERROR: ", err)
        }
        time.Sleep(30 * time.Second)
    }
    time.Sleep(600 * time.Second)
}
goroutine 35 [running]:
runtime/pprof.writeGoroutineStacks(0x382178, 0xc08203a140, 0x0, 0x0)
    D:/Go/src/pkg/runtime/pprof/pprof.go:511 +0x93
runtime/pprof.writeGoroutine(0x382178, 0xc08203a140, 0x2, 0x0, 0x0)
    D:/Go/src/pkg/runtime/pprof/pprof.go:500 +0x55
runtime/pprof.(*Profile).WriteTo(0x904e80, 0x382178, 0xc08203a140, 0x2, 0x0, 0x0)
    D:/Go/src/pkg/runtime/pprof/pprof.go:229 +0xda
net/http/pprof.handler.ServeHTTP(0xc08201ae51, 0x9, 0x3820f0, 0xc08203a140, 0xc08201edd0)
    D:/Go/src/pkg/net/http/pprof/pprof.go:165 +0x277
net/http/pprof.Index(0x3820f0, 0xc08203a140, 0xc08201edd0)
    D:/Go/src/pkg/net/http/pprof/pprof.go:177 +0x167
net/http.HandlerFunc.ServeHTTP(0x7e6368, 0x3820f0, 0xc08203a140, 0xc08201edd0)
    D:/Go/src/pkg/net/http/server.go:1235 +0x47
net/http.(*ServeMux).ServeHTTP(0xc08201a090, 0x3820f0, 0xc08203a140, 0xc08201edd0)
    D:/Go/src/pkg/net/http/server.go:1511 +0x1aa
net/http.serverHandler.ServeHTTP(0xc08200e5a0, 0x3820f0, 0xc08203a140, 0xc08201edd0)
    D:/Go/src/pkg/net/http/server.go:1673 +0x1a6
net/http.(*conn).serve(0xc082048600)
    D:/Go/src/pkg/net/http/server.go:1174 +0xa85
created by net/http.(*Server).Serve
    D:/Go/src/pkg/net/http/server.go:1721 +0x31a
goroutine 16 [sleep, 3 minutes]:
time.Sleep(0x8bb2c97000)
    C:/Users/ADMINI~1/AppData/Local/Temp/2/makerelease686069423/go/src/pkg/runtime/time.goc:39 +0x38
main.main()
    D:/workspace/beetalk_server/go_projects/src/garena.com/TestSMS/TestSMS.go:75 +0x89c
goroutine 19 [finalizer wait, 7 minutes]:
runtime.park(0x4160d0, 0x910c78, 0x90e609)
    D:/Go/src/pkg/runtime/proc.c:1369 +0xac
runtime.parkunlock(0x910c78, 0x90e609)
    D:/Go/src/pkg/runtime/proc.c:1385 +0x42
runfinq()
    D:/Go/src/pkg/runtime/mgc0.c:2644 +0xdd
runtime.goexit()
    D:/Go/src/pkg/runtime/proc.c:1445
goroutine 24 [chan receive, 6 minutes]:
net/http.(*persistConn).readLoop(0xc08203e160)
    D:/Go/src/pkg/net/http/transport.go:798 +0x312
created by net/http.(*Transport).dialConn
    D:/Go/src/pkg/net/http/transport.go:600 +0x946
goroutine 21 [IO wait]:
net.runtime_pollWait(0x381dc0, 0x72, 0x0)
    C:/Users/ADMINI~1/AppData/Local/Temp/2/makerelease686069423/go/src/pkg/runtime/netpoll.goc:146 +0x6d
net.(*pollDesc).Wait(0xc082080170, 0x72, 0x0, 0x0)
    D:/Go/src/pkg/net/fd_poll_runtime.go:84 +0x4d
net.(*ioSrv).ExecIO(0xc082038078, 0xc082080060, 0x750910, 0x8, 0xc082000980,
0xc082080480, 0x0, 0x0)
    D:/Go/src/pkg/net/fd_windows.go:188 +0x242
net.(*netFD).acceptOne(0xc082080000, 0x7e6298, 0xc08205a1c0, 0x2, 0x2, 0xc082080060,
0x7167a0, 0x0, 0x0)
    D:/Go/src/pkg/net/fd_windows.go:539 +0x3c7
net.(*netFD).accept(0xc082080000, 0x7e6298, 0x0, 0x0, 0x0)
    D:/Go/src/pkg/net/fd_windows.go:566 +0x187
net.(*TCPListener).AcceptTCP(0xc0820380d8, 0x45e0ca, 0x0, 0x0)
    D:/Go/src/pkg/net/tcpsock_posix.go:234 +0x64
net/http.tcpKeepAliveListener.Accept(0xc0820380d8, 0x0, 0x0, 0x0, 0x0)
    D:/Go/src/pkg/net/http/server.go:1947 +0x52
net/http.(*Server).Serve(0xc08200e5a0, 0x381f48, 0xc0820380d8, 0x0, 0x0)
    D:/Go/src/pkg/net/http/server.go:1698 +0x98
net/http.(*Server).ListenAndServe(0xc08200e5a0, 0x0, 0x0)
    D:/Go/src/pkg/net/http/server.go:1688 +0x154
net/http.ListenAndServe(0x7325f0, 0x5, 0x0, 0x0, 0x0, 0x0)
    D:/Go/src/pkg/net/http/server.go:1778 +0x80
created by main.main
    D:/workspace/beetalk_server/go_projects/src/garena.com/TestSMS/TestSMS.go:45 +0x59
goroutine 45 [IO wait]:
net.runtime_pollWait(0x381e70, 0x72, 0x0)
    C:/Users/ADMINI~1/AppData/Local/Temp/2/makerelease686069423/go/src/pkg/runtime/netpoll.goc:146 +0x6d
net.(*pollDesc).Wait(0xc0820802f0, 0x72, 0x0, 0x0)
    D:/Go/src/pkg/net/fd_poll_runtime.go:84 +0x4d
net.(*ioSrv).ExecIO(0xc082038078, 0xc0820801e0, 0x73ab90, 0x7, 0x7e6228, 0x0, 0x0, 0x0)
    D:/Go/src/pkg/net/fd_windows.go:188 +0x242
net.(*netFD).Read(0xc082080180, 0xc082070000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
    D:/Go/src/pkg/net/fd_windows.go:451 +0x156
net.(*conn).Read(0xc082038060, 0xc082070000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
    D:/Go/src/pkg/net/net.go:122 +0xee
net/http.(*liveSwitchReader).Read(0xc0820482a8, 0xc082070000, 0x1000, 0x1000, 0x0, 0x0,
0x0)
    D:/Go/src/pkg/net/http/server.go:206 +0xb6
io.(*LimitedReader).Read(0xc0820053a0, 0xc082070000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
    D:/Go/src/pkg/io/io.go:399 +0xd7
bufio.(*Reader).fill(0xc08200ee40)
    D:/Go/src/pkg/bufio/bufio.go:97 +0x1ba
bufio.(*Reader).ReadSlice(0xc08200ee40, 0xc08203e00a, 0x0, 0x0, 0x0, 0x0, 0x0)
    D:/Go/src/pkg/bufio/bufio.go:298 +0x233
bufio.(*Reader).ReadLine(0xc08200ee40, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
    D:/Go/src/pkg/bufio/bufio.go:326 +0x70
net/textproto.(*Reader).readLineSlice(0xc08201ae10, 0x0, 0x0, 0x0, 0x0, 0x0)
    D:/Go/src/pkg/net/textproto/reader.go:55 +0xa4
net/textproto.(*Reader).ReadLine(0xc08201ae10, 0x0, 0x0, 0x0, 0x0)
    D:/Go/src/pkg/net/textproto/reader.go:36 +0x55
net/http.ReadRequest(0xc08200ee40, 0xc08201ef70, 0x0, 0x0)
    D:/Go/src/pkg/net/http/request.go:556 +0xce
net/http.(*conn).readRequest(0xc082048280, 0x0, 0x0, 0x0)
    D:/Go/src/pkg/net/http/server.go:577 +0x27d
net/http.(*conn).serve(0xc082048280)
    D:/Go/src/pkg/net/http/server.go:1132 +0x625
created by net/http.(*Server).Serve
    D:/Go/src/pkg/net/http/server.go:1721 +0x31a
goroutine 33 [chan receive, 6 minutes]:
net/http.(*persistConn).readLoop(0xc08203e420)
    D:/Go/src/pkg/net/http/transport.go:798 +0x312
created by net/http.(*Transport).dialConn
    D:/Go/src/pkg/net/http/transport.go:600 +0x946
goroutine 39 [chan receive, 3 minutes]:
net/http.(*persistConn).readLoop(0xc08203e6e0)
    D:/Go/src/pkg/net/http/transport.go:798 +0x312
created by net/http.(*Transport).dialConn
    D:/Go/src/pkg/net/http/transport.go:600 +0x946

bradfitz · 2014-12-04T18:47:51Z

Comment 10:

That is neither complete, nor minimal. I can't run it and see the problem because it's
not complete. And it has a bunch of unrelated stuff still in it.
I suggest taking this to the golang-nuts@ mailing list where others can help you debug.
This feels like the wrong venue.

gopherbot · 2014-12-05T02:44:50Z

Comment 11 by ronee.9:

Sorry for that. I cannot provide a runnable code, because it is related to a commercial
account. And I only see this problem when I am post msg to this remote site (which is
provide by other company). I will try to reproduce this problem by building a simple
client and server and talking this to golang-nuts. Thanks for the reply

gopherbot · 2014-12-05T03:33:19Z

Comment 12 by ronee.9:

OK, finally find out the reason: it is caused by
this code: output, _ := httputil.DumpRequestOut(req, true). I guess there is some issue
while this function reads from the Reader. We should only use this in debug, not in
product:)
when I comment out this code, the problem solved.

gopherbot · 2014-12-05T04:25:15Z

Comment 13 by ronee.9:

Yes, confirmed, it is a leak in httputil.DumpRequestOut. This issue is claimed been
closed by revision 490c2d4fda2b.
However, it still exist in latest go version, and that is the exact reason for my
problem. The test code is here: http://play.golang.org/p/D77HaPiS_3
we can see 10 can receive block at
0x9f920 net/http.(*persistConn).readLoop+0x420  /tmp/sandbox/go/src/pkg/net/http/transport.go:798
We can continue this issue at https://golang.org/issue/7869

gopherbot added workingasintended labels Dec 5, 2014

bradfitz modified the milestone: Go1.5 Dec 16, 2014

bradfitz removed the release-go1.5 label Dec 16, 2014

golang locked and limited conversation to collaborators Jun 25, 2016

gopherbot added the FrozenDueToAge label Jun 25, 2016

This issue was closed.

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

net/http: Goroutine leak in http client/transport #9092

net/http: Goroutine leak in http client/transport #9092

gopherbot commented Nov 12, 2014

gopherbot commented Nov 12, 2014

ianlancetaylor commented Nov 12, 2014

bradfitz commented Nov 12, 2014

gopherbot commented Dec 3, 2014

bradfitz commented Dec 3, 2014

gopherbot commented Dec 3, 2014

bradfitz commented Dec 3, 2014

gopherbot commented Dec 3, 2014

gopherbot commented Dec 3, 2014

bradfitz commented Dec 4, 2014

gopherbot commented Dec 5, 2014

gopherbot commented Dec 5, 2014

gopherbot commented Dec 5, 2014

net/http: Goroutine leak in http client/transport #9092

net/http: Goroutine leak in http client/transport #9092

Comments

gopherbot commented Nov 12, 2014

gopherbot commented Nov 12, 2014

ianlancetaylor commented Nov 12, 2014

bradfitz commented Nov 12, 2014

gopherbot commented Dec 3, 2014

bradfitz commented Dec 3, 2014

gopherbot commented Dec 3, 2014

bradfitz commented Dec 3, 2014

gopherbot commented Dec 3, 2014

gopherbot commented Dec 3, 2014

bradfitz commented Dec 4, 2014

gopherbot commented Dec 5, 2014

gopherbot commented Dec 5, 2014

gopherbot commented Dec 5, 2014