Re: Issue 9092 in go: net/http: Goroutine leak in http client/transport

[g...@googlecode.com]

Updates:
Summary: net/http: Goroutine leak in http client/transport
Cc: brad...@golang.org
Labels: Repo-Main Release-Go1.5

Comment #2 on issue 9092 by i...@golang.org: net/http: Goroutine leak in
http client/transport
https://code.google.com/p/go/issues/detail?id=9092

(No comment was entered for this change.)

--
You received this message because this project is configured to send all
issue notifications to this address.
You may adjust your notification preferences at:
https://code.google.com/hosting/settings

[g...@googlecode.com]

Updates:
Status: WorkingAsIntended

Comment #3 on issue 9092 by brad...@golang.org: net/http: Goroutine leak

in http client/transport
https://code.google.com/p/go/issues/detail?id=9092

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.

[g...@googlecode.com]

Comment #4 on issue 9092 by rone...@gmail.com: net/http: Goroutine leak in
http client/transport
https://code.google.com/p/go/issues/detail?id=9092


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

[g...@googlecode.com]

Comment #5 on issue 9092 by brad...@golang.org: net/http: Goroutine leak

in http client/transport
https://code.google.com/p/go/issues/detail?id=9092

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.

[g...@googlecode.com]

Comment #6 on issue 9092 by rone...@gmail.com: net/http: Goroutine leak in
http client/transport
https://code.google.com/p/go/issues/detail?id=9092

Yes. I called it only once.

[g...@googlecode.com]

Comment #7 on issue 9092 by brad...@golang.org: net/http: Goroutine leak

in http client/transport
https://code.google.com/p/go/issues/detail?id=9092

Please post a complete but minimal reproduction program.

[g...@googlecode.com]

Comment #8 on issue 9092 by rone...@gmail.com: net/http: Goroutine leak in
http client/transport
https://code.google.com/p/go/issues/detail?id=9092

OK, i will try to do it.

[g...@googlecode.com]

Comment #9 on issue 9092 by rone...@gmail.com: net/http: Goroutine leak in
http client/transport
https://code.google.com/p/go/issues/detail?id=9092

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

[g...@googlecode.com]

Comment #10 on issue 9092 by brad...@golang.org: net/http: Goroutine leak

in http client/transport
https://code.google.com/p/go/issues/detail?id=9092

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.

[g...@googlecode.com]

Comment #11 on issue 9092 by rone...@gmail.com: net/http: Goroutine leak in
http client/transport
https://code.google.com/p/go/issues/detail?id=9092

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

[g...@googlecode.com]

Comment #12 on issue 9092 by rone...@gmail.com: net/http: Goroutine leak in
http client/transport
https://code.google.com/p/go/issues/detail?id=9092

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.

[g...@googlecode.com]

Comment #13 on issue 9092 by rone...@gmail.com: net/http: Goroutine leak in
http client/transport
https://code.google.com/p/go/issues/detail?id=9092

Yes, confirmed, it is a leak in httputil.DumpRequestOut. This issue is
claimed been closed by <a
href="/p/go/source/detail?r=490c2d4fda2b">revision 490c2d4fda2b</a>.
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://code.google.com/p/go/issues/detail?id=7869