What could cause all of these stuck goroutines in net/http?

[Blake Caldwell]

My long-running service dials out to several machines. I'm making https POST requests as well as using net.Dial to then open up SSH connections. After a while, I'm seeing hundreds of stuck goroutines with this exact stack trace. I'm guessing these are from the https POSTs, since it's starting in http/transport. I'm making sure to call .Body.Close() on my http responses. 

Any ideas?

goroutine 24297553 [semacquire, 296 minutes]:
sync.(*WaitGroup).Wait(0xc20819e840)
	/usr/src/go/src/sync/waitgroup.go:132 +0x169
net.(*singleflight).Do(0x9fba90, 0xc208999a00, 0x15, 0xc208e8a548, 0x0, 0x0, 0x0, 0x0, 0x410d38)
	/usr/src/go/src/net/singleflight.go:53 +0x143
net.lookupIPMerge(0xc208999a00, 0x15, 0x0, 0x0, 0x0, 0x0, 0x0)
	/usr/src/go/src/net/lookup.go:42 +0xae
net.lookupIPDeadline(0xc208999a00, 0x15, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
	/usr/src/go/src/net/lookup.go:64 +0x12d
net.resolveInternetAddr(0x8024d0, 0x3, 0xc208999a00, 0x19, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
	/usr/src/go/src/net/ipsock.go:285 +0x49b
net.resolveAddr(0x7f5890, 0x4, 0x8024d0, 0x3, 0xc208999a00, 0x19, 0x0, 0x0, 0x0, 0x0, ...)
	/usr/src/go/src/net/dial.go:110 +0x378
net.(*Dialer).Dial(0xc208d55e80, 0x8024d0, 0x3, 0xc208999a00, 0x19, 0x0, 0x0, 0x0, 0x0)
	/usr/src/go/src/net/dial.go:158 +0xf6
net.Dial(0x8024d0, 0x3, 0xc208999a00, 0x19, 0x0, 0x0, 0x0, 0x0)
	/usr/src/go/src/net/dial.go:143 +0x8a
net/http.(*Transport).dial(0xc20806c090, 0x8024d0, 0x3, 0xc208999a00, 0x19, 0x0, 0x0, 0x0, 0x0)
	/usr/src/go/src/net/http/transport.go:481 +0xcf
net/http.(*Transport).dialConn(0xc20806c090, 0x0, 0xc2087edb90, 0x5, 0xc208999a00, 0x19, 0x6d95e0, 0x0, 0x0)
	/usr/src/go/src/net/http/transport.go:564 +0x1678
net/http.func·019()
	/usr/src/go/src/net/http/transport.go:520 +0x42
created by net/http.(*Transport).getConn
	/usr/src/go/src/net/http/transport.go:522 +0x335

[maxpow...@gmail.com]

Can you post a code sample to the playground?  It's really hard to comment on anything without seeing it.

[Dave Cheney]

Has the DNS server this machine is attempting to resolve with crapped out ?

[Blake Caldwell]

I don't think so. All the other services are working fine.

[Blake Caldwell]

Maybe I'm using HttpClient poorly? I have a single instance that's shared for all requests.

Here's more or less what I'm doing:

http://play.golang.org/p/_0WpZhHJmB

Our sysadmin says there's a bunch of old open connections from this process to our load balancer, which is out in front of the HTTP server I'm trying to reach. If I let this go without restarting for a couple more days, it gets in a state where it can't even dial out via net.Dial in another area in our code.

Thanks!

[Mike Ossareh]

My past experience of this is that there is some code path where `resp.Body.Close()` is not being called.

Are you sure you're always closing the body?

--
You received this message because you are subscribed to the Google Groups "golang-nuts" group.
To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Blake Caldwell]

Yep. Here's how I'm using it:

http://play.golang.org/p/_0WpZhHJmB

[Harmen B]

Not that it'll help with the underlying problem, but you can set a .Timeout on the client, so you know those won't hang around.

On Fri, Jan 30, 2015 at 8:00 AM, Blake Caldwell <blakec...@gmail.com> wrote:

Yep. Here's how I'm using it:

http://play.golang.org/p/_0WpZhHJmB

[Blake Caldwell]

Yeah, it seems there's a lot of different places I can add timeouts for HTTP connections. I'm trying to figure out which to implement.

[Blake Caldwell]

I should mention one other thing that's weird with what I'm doing here. I'm never reading the HTTP response body. For the request I'm using, I just need the headers. I'm still calling "defer resp.Body.Close()" though. This shouldn't be causing any issues, right?

[Blake Caldwell]

Now that I'm thinking about it... The web endpoint I'm hitting should have an empty body, sending me everything I need in the headers, so I ignore the body. I'm wondering what happens if the server experiences a problem and dumps out a giant stack trace or something. In that case, maybe the io.ReadCloser Body's buffer fills up, and doesn't like to be closed without all the data being read. 

I'm seeing others saying that you should always consume the entire response:

https://groups.google.com/forum/#!topic/golang-nuts/148riho42sU

"I believe you have to actually read the entire body yourself — with something like io.Copy + ioutil.Discard if 
you don’t care about it. If you just call response.Body.Close() without reading till EOF, the conn is just closed and discarded (not reused)."

Is this likely my problem?

On Friday, January 30, 2015 at 12:35:36 AM UTC-5, Blake Caldwell wrote:

[Jesse McNelis]

On Sat, Jan 31, 2015 at 12:25 AM, Blake Caldwell <bl...@fogcreek.com> wrote:
> Now that I'm thinking about it... The web endpoint I'm hitting should have
> an empty body, sending me everything I need in the headers, so I ignore the
> body. I'm wondering what happens if the server experiences a problem and
> dumps out a giant stack trace or something. In that case, maybe the
> io.ReadCloser Body's buffer fills up, and doesn't like to be closed without
> all the data being read.

This is no longer true.

> you don’t care about it. If you just call response.Body.Close() without
> reading till EOF, the conn is just closed and discarded (not reused)."
>
> Is this likely my problem?

The stacktrace you've posted indicates that you're not even getting to
make the http requests.
Your goroutines are getting stuck trying to do DNS lookups before the request.

Is there some kind of firewall on this machine that is preventing the
DNS lookups?

[Dave Cheney]

Are you issuing a HEAD request ?

[Blake Caldwell]

Nope. I'm posting data, and only reading the headers.

[Blake Caldwell]

Other services are having no problems with DNS. Looking more into the stack trace:

it's stuck on a WaitGroup in net.(*singleflight).Do, which does this:

// Do executes and returns the results of the given function, making

// sure that only one execution is in-flight for a given key at a

// time. If a duplicate comes in, the duplicate caller waits for the

// original to complete and receives the same results.

// The return value shared indicates whether v was given to multiple callers.

That's being called by this:

// lookupIPMerge wraps lookupIP, but makes sure that for any given

// host, only one lookup is in-flight at a time. The returned memory

// is always owned by the caller.

func lookupIPMerge(host string) (addrs []IP, err error) {

addrsi, err, shared := lookupGroup.Do(host, func() (interface{}, error) {

return lookupIP(host)

})

return lookupIPReturn(addrsi, err, shared)

}

If I'm understanding the stack trace properly, it's trying to dial, which is doing a DNS lookup first, and it only allows one DNS call at a time. For some reason, one DNS call must have gotten stuck, which backs up everything past it. However, not all requests are stuck. These slowly start to build up. I'm not yet sure why this isn't completely blocking for everyone.

[Andrew Gerrand]

On 31 January 2015 at 00:25, Blake Caldwell <bl...@fogcreek.com> wrote:

Now that I'm thinking about it... The web endpoint I'm hitting should have an empty body, sending me everything I need in the headers, so I ignore the body.

You MUST call resp.Body.Close() after each HTTP request, whether you care about the body or not.

Otherwise, the connection to the server will be kept open. What you're seeing corresponds to what I see on my machine when I run out of available file descriptors, which is what happens when you keep too many connections open.

Apologies if I missed it, but are you calling resp.Body.Close() after each request?

Andrew

[Blake Caldwell]

Yep - here's how I'm doing it:

http://play.golang.org/p/_0WpZhHJmB

resp, err := HTTPClient().PostForm(urlToPostTo, url.Values{"foo": {"foo"}, "bar": {"bar"}})

if err != nil {

return fmt.Errorf("Error making request: %s", err.Error())

}

defer resp.Body.Close()

I didn't think I needed to close it in the error block, but it does look like it's possible to get both an error and non-nil response, via:

https://golang.org/src/net/http/client.go

   394 urlErr := &url.Error{

   395 Op:  method[0:1] + strings.ToLower(method[1:]),

   396 URL: urlStr,

   397 Err: err,

   398 }

   399

   400 if redirectFailed {

   401 // Special case for Go 1 compatibility: return both the response

   402 // and an error if the CheckRedirect function failed.

   403 // See http://golang.org/issue/3795

   404 return resp, urlErr

   405 }

[Andrew Gerrand]

In the section "// do something with response" are you actually consuming the body?

How long does that code take to execute?

Consider consuming the body and closing it immediately, before doing anything else:

resp, err := HTTPClient().PostForm(urlToPostTo, url.Values{"foo": {"foo"}, "bar": {"bar"}})

if err != nil {

return err

}

body, err := ioutil.ReadAll(resp.Body)

resp.Body.Close()

if err != nil {

return err

}

// do something with response

--

[Blake Caldwell]

I'm not touching the body at all, besides the deferred close. All I'm doing with resp is a bunch of "resp.Header.Get" calls. 

Here's a snippet from Jesse's response above:

BEGIN-----

> Now that I'm thinking about it... The web endpoint I'm hitting should have 
> an empty body, sending me everything I need in the headers, so I ignore the 

> body. I'm wondering what happens if the server experiences a problem and 
> dumps out a giant stack trace or something. In that case, maybe the 
> io.ReadCloser Body's buffer fills up, and doesn't like to be closed without 
> all the data being read. 

This is no longer true. 

END -----

[Blake Caldwell]

Oh, and these web requests take about 50-100ms, and the rest of my function here is quick - nothing else time-consuming happens here

[Joshua Boelter]

Blake,

I think you're right on the stacktrace. A DNS call is blocking and causing all subsequent calls with the same dns name/key to wait for the initial one to complete.  The stacktrace also shows it going through lookup.go:64 (deadline.IsZero) which is not using a deadline/timeout for the lookup itself.  Any timeout would be in the system call.

What platform/OS are you on? go1.4.1?  The actual lookupIP call is different per platform (e.g. unix eventually goes through cgoLookupIPCNAME which is calling getaddrinfo) in cgo_unix.go:84

-Josh

[Blake Caldwell]

I'm running on Linux on 1.4. I haven't yet upgraded to 1.4.1. Thanks!

I'm planning on adding timeouts. That might prevent this situation again, but not fix the underlying issue. That said, I'm also looking through the different ways to time connections out. One of them scares me a little - using conn.SetTimeout in the http.Transport. I read some people saying that this could cause issues with keepalives.

Here's what I'm currently tinkering with, but haven't tested:

http://play.golang.org/p/FVxJn0OiEH

[Blake Caldwell]

Here's a bunch more info. I went through the full stack trace output to see what else was in there. I should have done this before. Notice that stuck syscall? I'm not sure if that's the oldest of the stuck goroutines - I need to check that to see if it's the root of all problems. Thoughts?

**** whoa, interesting

goroutine 23885395 [syscall, 228 minutes, locked to thread]:

net._C2func_getaddrinfo(0x1924010, 0x0, 0xc2087a9278, 0xc2087a91c8, 0x301befcd00000000, 0x0, 0x0)

/usr/src/go/src/net/:26 +0x55

net.cgoLookupIPCNAME(0xc208bd45c0, 0x15, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)

/usr/src/go/src/net/cgo_unix.go:96 +0x1c5

net.cgoLookupIP(0xc208bd45c0, 0x15, 0x0, 0x0, 0x0, 0x0, 0x0, 0xc2080da240)

/usr/src/go/src/net/cgo_unix.go:148 +0x65

net.lookupIP(0xc208bd45c0, 0x15, 0x0, 0x0, 0x0, 0x0, 0x0)

/usr/src/go/src/net/lookup_unix.go:64 +0x5f

net.func·025(0x0, 0x0, 0x0, 0x0)

/usr/src/go/src/net/lookup.go:41 +0x55

net.(*singleflight).doCall(0x9fba90, 0xc20819e840, 0xc208bd45c0, 0x15, 0xc2087a9548)

/usr/src/go/src/net/singleflight.go:91 +0x2f

net.(*singleflight).Do(0x9fba90, 0xc208bd45c0, 0x15, 0xc2087a9548, 0x0, 0x0, 0x0, 0x0, 0x410d38)

/usr/src/go/src/net/singleflight.go:61 +0x280

net.lookupIPMerge(0xc208bd45c0, 0x15, 0x0, 0x0, 0x0, 0x0, 0x0)

/usr/src/go/src/net/lookup.go:42 +0xae

net.lookupIPDeadline(0xc208bd45c0, 0x15, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)

/usr/src/go/src/net/lookup.go:64 +0x12d

net.resolveInternetAddr(0x8024d0, 0x3, 0xc208bd45c0, 0x19, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)

/usr/src/go/src/net/ipsock.go:285 +0x49b

net.resolveAddr(0x7f5890, 0x4, 0x8024d0, 0x3, 0xc208bd45c0, 0x19, 0x0, 0x0, 0x0, 0x0, ...)

/usr/src/go/src/net/dial.go:110 +0x378

net.(*Dialer).Dial(0xc2080c6580, 0x8024d0, 0x3, 0xc208bd45c0, 0x19, 0x0, 0x0, 0x0, 0x0)

/usr/src/go/src/net/dial.go:158 +0xf6

net.Dial(0x8024d0, 0x3, 0xc208bd45c0, 0x19, 0x0, 0x0, 0x0, 0x0)

/usr/src/go/src/net/dial.go:143 +0x8a

net/http.(*Transport).dial(0xc20806c090, 0x8024d0, 0x3, 0xc208bd45c0, 0x19, 0x0, 0x0, 0x0, 0x0)

/usr/src/go/src/net/http/transport.go:481 +0xcf

net/http.(*Transport).dialConn(0xc20806c090, 0x0, 0xc208216420, 0x5, 0xc208bd45c0, 0x19, 0xc2081627b8, 0x0, 0x0)

/usr/src/go/src/net/http/transport.go:564 +0x1678

net/http.func·019()

/usr/src/go/src/net/http/transport.go:520 +0x42

created by net/http.(*Transport).getConn

/usr/src/go/src/net/http/transport.go:522 +0x335

*** Tons of these

goroutine 24192220 [semacquire, 14 minutes]:

sync.(*WaitGroup).Wait(0xc20819e840)

/usr/src/go/src/sync/waitgroup.go:132 +0x169

net.(*singleflight).Do(0x9fba90, 0xc208ba3d20, 0x15, 0xc208445548, 0x0, 0x0, 0x0, 0x0, 0x410d38)

/usr/src/go/src/net/singleflight.go:53 +0x143

net.lookupIPMerge(0xc208ba3d20, 0x15, 0x0, 0x0, 0x0, 0x0, 0x0)

/usr/src/go/src/net/lookup.go:42 +0xae

net.lookupIPDeadline(0xc208ba3d20, 0x15, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)

/usr/src/go/src/net/lookup.go:64 +0x12d

net.resolveInternetAddr(0x8024d0, 0x3, 0xc208ba3d20, 0x19, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)

/usr/src/go/src/net/ipsock.go:285 +0x49b

net.resolveAddr(0x7f5890, 0x4, 0x8024d0, 0x3, 0xc208ba3d20, 0x19, 0x0, 0xc200000000, 0x0, 0x0, ...)

/usr/src/go/src/net/dial.go:110 +0x378

net.(*Dialer).Dial(0xc208bacf00, 0x8024d0, 0x3, 0xc208ba3d20, 0x19, 0x0, 0x0, 0x0, 0x0)

/usr/src/go/src/net/dial.go:158 +0xf6

net.Dial(0x8024d0, 0x3, 0xc208ba3d20, 0x19, 0x0, 0x0, 0x0, 0x0)

/usr/src/go/src/net/dial.go:143 +0x8a

net/http.(*Transport).dial(0xc20806c090, 0x8024d0, 0x3, 0xc208ba3d20, 0x19, 0x0, 0x0, 0x0, 0x0)

/usr/src/go/src/net/http/transport.go:481 +0xcf

net/http.(*Transport).dialConn(0xc20806c090, 0x0, 0xc2087ed350, 0x5, 0xc208ba3d20, 0x19, 0xc20858a000, 0x0, 0x0)

/usr/src/go/src/net/http/transport.go:564 +0x1678

net/http.func·019()

/usr/src/go/src/net/http/transport.go:520 +0x42

created by net/http.(*Transport).getConn

/usr/src/go/src/net/http/transport.go:522 +0x335

*** A bunch of these

goroutine 24117026 [select, 65 minutes]:

net/http.(*Transport).getConn(0xc20806c090, 0xc208bd3e10, 0x0, 0xc208615620, 0x5, 0xc2081bb1c0, 0x19, 0x0, 0x0, 0x0)

/usr/src/go/src/net/http/transport.go:525 +0x608

net/http.(*Transport).RoundTrip(0xc20806c090, 0xc208bd3e10, 0xc2086156b0, 0x0, 0x0)

/usr/src/go/src/net/http/transport.go:228 +0x4d4

net/http.send(0xc208bd3e10, 0x7f8a47c85f00, 0xc20806c090, 0x2a, 0x0, 0x0)

/usr/src/go/src/net/http/client.go:219 +0x4fc

net/http.(*Client).send(0x9fc3a0, 0xc208bd3e10, 0x2a, 0x0, 0x0)

/usr/src/go/src/net/http/client.go:142 +0x15b

net/http.(*Client).doFollowingRedirects(0x9fc3a0, 0xc208bd3e10, 0x8bf428, 0x0, 0x0, 0x0)

/usr/src/go/src/net/http/client.go:367 +0xb25

net/http.(*Client).Post(0x9fc3a0, 0xc208615620, 0x2a, 0x865a50, 0x21, 0x7f8a47c88e70, 0xc2081bb1a0, 0x0, 0x0, 0x0)

/usr/src/go/src/net/http/client.go:441 +0x10d

net/http.(*Client).PostForm(0x9fc3a0, 0xc208615620, 0x2a, 0xc208615650, 0x1, 0x0, 0x0)

/usr/src/go/src/net/http/client.go:461 +0x11c

I<**** MY CODE BELOW THIS LINE ****>

On Friday, January 30, 2015 at 12:35:36 AM UTC-5, Blake Caldwell wrote:

[Blake Caldwell]

Here's the same goroutines in a more readable form: https://gist.githubusercontent.com/wblakecaldwell/ed43ad11271200403f5e/raw/4c709da89f19eb25e982ba973dc3825626a8fa00/gistfile1.txt

On Friday, January 30, 2015 at 12:35:36 AM UTC-5, Blake Caldwell wrote:

[Dave Cheney]

That's the cause. Your system's libc dns resolver jammed there, anyone else trying to resolve that name will wait on that call to return. Different names are unaffected, nor names that are cached.

Earlier in the thread there was a recommendation for you to recompile Go to disable the cgo dns resolver and use the Go based one. I don't hold a lot of stock on the -netgo magic tag while building your program model, I prefer to rebuild go with CGO_ENABLED=0 set. Either will ensure that the pure Go dns resolver is used.

Dave

[Blake Caldwell]

AWESOME.

Thanks, Dave. I saw Joshua's mention of cgo, but didn't know what to do about it. I'll give this a shot! And yeah, this is exactly the behavior I'm seeing - connections to one domain cease to work.

[Dave Cheney]

Which OS are you using. Go has exposed serious bugs in most dns resolvers.

[Blake Caldwell]

I believe we're using Debian 7.6

[dja...@gmail.com]

cat /etc/debian_version

[Blake Caldwell]

I shouldn't have said "I believe". That's what I did, sorry :)

debian 7.6

[Blake Caldwell]

Just... this?

cd /usr/src/go/src

CGO_ENABLED=0 GOOS=linux ./make.bash

cd $GOPATH

CGO_ENABLED=0 GOOS=linux /usr/src/go/bin/go build

and, of course, making sure to use that go binary that I just built.

Pretty sure I did everything right. The "file" command shows me this about my binary:

ELF 64-bit LSB  executable, x86-64, version 1 (SYSV), statically linked, not stripped

Thanks again!

- Blake

[Dave Cheney]

If you are using a packaged version of Go I recommend these steps.

1. uninstall the packaged version

2. $ git clone https://go.googlesource.com/go

$ cd go
$ git checkout go1.4.1

3. env CGO_ENABLED=0 ./all.bash

4. make sure $HOME/go is in your $PATH

[Blake Caldwell]

As a follow-up, my CGO-disabled service has been running in production for about a week with no DNS problems. It's still a little early to call it, but I think the !CGO route mighta fixed the issue.

Thanks everyone!

[Dave Cheney]

Good to know. Thanks for following up.