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: Client.Timeout is not propagated to Request's Context Deadline #31657

Open
esuhadolnik opened this issue Apr 24, 2019 · 13 comments

Comments

Projects
None yet
5 participants
@esuhadolnik
Copy link

commented Apr 24, 2019

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

go version go1.12.2 darwin/amd64

Does this issue reproduce with the latest release?

Yes.

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

go env Output
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/emily/Library/Caches/go-build"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOOS="darwin"
GOPATH="/Users/emily/workspace/go"
GOPROXY=""
GORACE=""
GOROOT="/usr/local/Cellar/go/1.12.2/libexec"
GOTMPDIR=""
GOTOOLDIR="/usr/local/Cellar/go/1.12.2/libexec/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/37/cw9wkbds2c7gn9371lwx95hrcxlj7k/T/go-build960903312=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

  1. Simple service: https://play.golang.org/p/EG0LLj_PFvb
  2. Used Artillery to generate small amount (1 TPS) of continuous load to service
  3. Used Network Link Conditioner to cause a network glitch to occur (100% Loss: 100% Packets Dropped)

What did you expect to see?

Goroutines would stay steady or drop off as requests aren't able to exceed and timeouts are being met.

What did you see instead?

Goroutines take off while the request returns the expected error. The goroutines increase and increase until they eventually drop off, then they increase and drop off repeats.

@bradfitz

This comment has been minimized.

Copy link
Member

commented Apr 24, 2019

Is Artillery running from localhost and hitting your localhost? Maybe Network Link Conditioner doesn't degrade that traffic, so server goroutines pile up but your clients hitting google.com are getting 100% packet loss.

You could hit Control-\ (SIGQUIT) and see a goroutine dump and see what's piling up and confirm the theory above.

@esuhadolnik

This comment has been minimized.

Copy link
Author

commented Apr 25, 2019

Yes, Artillery is running from my machine and hitting my localhost. I was also able to reproduce the issue from Postman as well as just using curl to hit localhost over and over.

Control-\ (SIGQUIT) Output
^\SIGQUIT: quit
PC=0x7fffd134abf2 m=0 sigcode=0

goroutine 0 [idle]:
runtime.pthread_cond_wait(0x1730d08, 0x1730cc8, 0x7fff00000000)
/usr/local/Cellar/go/1.12.2/libexec/src/runtime/sys_darwin.go:357 +0x3b
runtime.semasleep(0xffffffffffffffff, 0x104c06c)
/usr/local/Cellar/go/1.12.2/libexec/src/runtime/os_darwin.go:63 +0x85
runtime.notesleep(0x1730ac8)
/usr/local/Cellar/go/1.12.2/libexec/src/runtime/lock_sema.go:167 +0xe0
runtime.stopm()
/usr/local/Cellar/go/1.12.2/libexec/src/runtime/proc.go:1936 +0xc1
runtime.findrunnable(0xc000022000, 0x0)
/usr/local/Cellar/go/1.12.2/libexec/src/runtime/proc.go:2399 +0x54a
runtime.schedule()
/usr/local/Cellar/go/1.12.2/libexec/src/runtime/proc.go:2525 +0x21c
runtime.park_m(0xc000067980)
/usr/local/Cellar/go/1.12.2/libexec/src/runtime/proc.go:2605 +0xa1
runtime.mcall(0x105af4b)
/usr/local/Cellar/go/1.12.2/libexec/src/runtime/asm_amd64.s:299 +0x5b

goroutine 1 [IO wait]:
internal/poll.runtime_pollWait(0x18b6ea8, 0x72, 0x0)
/usr/local/Cellar/go/1.12.2/libexec/src/runtime/netpoll.go:182 +0x56
internal/poll.(*pollDesc).wait(0xc000144018, 0x72, 0x0, 0x0, 0x1402cf3)
/usr/local/Cellar/go/1.12.2/libexec/src/internal/poll/fd_poll_runtime.go:87 +0x9b
internal/poll.(*pollDesc).waitRead(...)
/usr/local/Cellar/go/1.12.2/libexec/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Accept(0xc000144000, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
/usr/local/Cellar/go/1.12.2/libexec/src/internal/poll/fd_unix.go:384 +0x1ba
net.(*netFD).accept(0xc000144000, 0xc0000d5d20, 0xc08be36dbd, 0xc000039000)
/usr/local/Cellar/go/1.12.2/libexec/src/net/fd_unix.go:238 +0x42
net.(*TCPListener).accept(0xc00014c000, 0x2a1c8be36dbd, 0x100000001, 0xc0000d5d60)
/usr/local/Cellar/go/1.12.2/libexec/src/net/tcpsock_posix.go:139 +0x32
net.(*TCPListener).AcceptTCP(0xc00014c000, 0xc0000d5d88, 0x10ad456, 0x5cc1d20f)
/usr/local/Cellar/go/1.12.2/libexec/src/net/tcpsock.go:247 +0x48
net/http.tcpKeepAliveListener.Accept(0xc00014c000, 0xc0000d5dd8, 0x18, 0xc000000180, 0x12b23b4)
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/server.go:3263 +0x2f
net/http.(*Server).Serve(0xc0001261a0, 0x148cb00, 0xc00014c000, 0x0, 0x0)
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/server.go:2858 +0x22d
net/http.(*Server).ListenAndServe(0xc0001261a0, 0x1c, 0x0)
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/server.go:2796 +0xe4
main.main()
/Users/emily/Desktop/main.go:39 +0x1fc

goroutine 4 [chan receive]:
main.startGoroutineGauge()
/Users/emily/Desktop/main.go:64 +0xd2
created by main.main
/Users/emily/Desktop/main.go:15 +0x47

goroutine 5 [IO wait]:
internal/poll.runtime_pollWait(0x18b6dd8, 0x72, 0x0)
/usr/local/Cellar/go/1.12.2/libexec/src/runtime/netpoll.go:182 +0x56
internal/poll.(*pollDesc).wait(0xc000144098, 0x72, 0x0, 0x0, 0x1402cf3)
/usr/local/Cellar/go/1.12.2/libexec/src/internal/poll/fd_poll_runtime.go:87 +0x9b
internal/poll.(*pollDesc).waitRead(...)
/usr/local/Cellar/go/1.12.2/libexec/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Accept(0xc000144080, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
/usr/local/Cellar/go/1.12.2/libexec/src/internal/poll/fd_unix.go:384 +0x1ba
net.(*netFD).accept(0xc000144080, 0x13d5080, 0x50, 0xc00013a050)
/usr/local/Cellar/go/1.12.2/libexec/src/net/fd_unix.go:238 +0x42
net.(*TCPListener).accept(0xc000124010, 0xc000038c00, 0x18166d0, 0x0)
/usr/local/Cellar/go/1.12.2/libexec/src/net/tcpsock_posix.go:139 +0x32
net.(*TCPListener).AcceptTCP(0xc000124010, 0x100df88, 0x30, 0x13d5080)
/usr/local/Cellar/go/1.12.2/libexec/src/net/tcpsock.go:247 +0x48
net/http.tcpKeepAliveListener.Accept(0xc000124010, 0x13d5080, 0xc000082480, 0x13964a0, 0x1720a10)
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/server.go:3263 +0x2f
net/http.(*Server).Serve(0xc00008c4e0, 0x148cb00, 0xc000124010, 0x0, 0x0)
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/server.go:2858 +0x22d
net/http.(*Server).ListenAndServe(0xc00008c4e0, 0xc00008c4e0, 0xc0000367c0)
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/server.go:2796 +0xe4
net/http.ListenAndServe(...)
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/server.go:3036
main.main.func1()
/Users/emily/Desktop/main.go:21 +0x141
created by main.main
/Users/emily/Desktop/main.go:18 +0x6f

goroutine 153 [select]:
net.cgoLookupIP(0x148cfc0, 0xc000094940, 0x14017bd, 0x3, 0xc0000923f0, 0xa, 0x0, 0x0, 0x0, 0x0, ...)
/usr/local/Cellar/go/1.12.2/libexec/src/net/cgo_unix.go:217 +0x195
net.(*Resolver).lookupIP(0x172f9e0, 0x148cfc0, 0xc000094940, 0x14017bd, 0x3, 0xc0000923f0, 0xa, 0x16fb1c0, 0xc0001656a8, 0xc000152480, ...)
/usr/local/Cellar/go/1.12.2/libexec/src/net/lookup_unix.go:96 +0x1a4
net.glob..func1(0x148cfc0, 0xc000094940, 0xc000080740, 0x14017bd, 0x3, 0xc0000923f0, 0xa, 0xc0001656d0, 0x105a070, 0xc000152180, ...)
/usr/local/Cellar/go/1.12.2/libexec/src/net/hook.go:23 +0x72
net.(*Resolver).lookupIPAddr.func1(0x0, 0x0, 0x0, 0x0)
/usr/local/Cellar/go/1.12.2/libexec/src/net/lookup.go:269 +0x116
internal/singleflight.(*Group).doCall(0x172f9f0, 0xc00013a690, 0xc000092400, 0xe, 0xc000094980)
/usr/local/Cellar/go/1.12.2/libexec/src/internal/singleflight/singleflight.go:95 +0x2e
created by internal/singleflight.(*Group).DoChan
/usr/local/Cellar/go/1.12.2/libexec/src/internal/singleflight/singleflight.go:88 +0x29d

goroutine 138 [IO wait]:
internal/poll.runtime_pollWait(0x18b6a98, 0x77, 0xc000152900)
/usr/local/Cellar/go/1.12.2/libexec/src/runtime/netpoll.go:182 +0x56
internal/poll.(*pollDesc).wait(0xc000120818, 0x77, 0x148cf00, 0xc00005a7c0, 0xc000120800)
/usr/local/Cellar/go/1.12.2/libexec/src/internal/poll/fd_poll_runtime.go:87 +0x9b
internal/poll.(*pollDesc).waitWrite(...)
/usr/local/Cellar/go/1.12.2/libexec/src/internal/poll/fd_poll_runtime.go:96
internal/poll.(*FD).WaitWrite(...)
/usr/local/Cellar/go/1.12.2/libexec/src/internal/poll/fd_unix.go:498
net.(*netFD).connect(0xc000120800, 0x148cfc0, 0xc00005a7c0, 0x0, 0x0, 0x1486540, 0xc00001c5a0, 0x0, 0x0, 0x0, ...)
/usr/local/Cellar/go/1.12.2/libexec/src/net/fd_unix.go:152 +0x284
net.(*netFD).dial(0xc000120800, 0x148cfc0, 0xc00005a7c0, 0x148edc0, 0x0, 0x148edc0, 0xc00011ed80, 0x0, 0xc00001a201, 0xc000200b78)
/usr/local/Cellar/go/1.12.2/libexec/src/net/sock_posix.go:149 +0xff
net.socket(0x148cfc0, 0xc00005a7c0, 0x14017bd, 0x3, 0x2, 0x1, 0x0, 0x0, 0x148edc0, 0x0, ...)
/usr/local/Cellar/go/1.12.2/libexec/src/net/sock_posix.go:70 +0x1c0
net.internetSocket(0x148cfc0, 0xc00005a7c0, 0x14017bd, 0x3, 0x148edc0, 0x0, 0x148edc0, 0xc00011ed80, 0x1, 0x0, ...)
/usr/local/Cellar/go/1.12.2/libexec/src/net/ipsock_posix.go:141 +0x141
net.(*sysDialer).doDialTCP(0xc000120780, 0x148cfc0, 0xc00005a7c0, 0x0, 0xc00011ed80, 0x139be80, 0x174c788, 0x0)
/usr/local/Cellar/go/1.12.2/libexec/src/net/tcpsock_posix.go:65 +0xc2
net.(*sysDialer).dialTCP(0xc000120780, 0x148cfc0, 0xc00005a7c0, 0x0, 0xc00011ed80, 0xc0001665b8, 0x11757ae, 0xbf289269b028d9de)
/usr/local/Cellar/go/1.12.2/libexec/src/net/tcpsock_posix.go:61 +0xd7
net.(*sysDialer).dialSingle(0xc000120780, 0x148cfc0, 0xc00005a7c0, 0x1488b80, 0xc00011ed80, 0x0, 0x0, 0x0, 0x0)
/usr/local/Cellar/go/1.12.2/libexec/src/net/dial.go:571 +0x34b
net.(*sysDialer).dialSerial(0xc000120780, 0x148cfc0, 0xc00005a7c0, 0xc000012470, 0x1, 0x1, 0x0, 0x0, 0x0, 0x0)
/usr/local/Cellar/go/1.12.2/libexec/src/net/dial.go:539 +0x221
net.(*sysDialer).dialParallel.func1(0x148cfc0, 0xc00005a7c0, 0xc000012401)
/usr/local/Cellar/go/1.12.2/libexec/src/net/dial.go:460 +0x95
created by net.(*sysDialer).dialParallel
/usr/local/Cellar/go/1.12.2/libexec/src/net/dial.go:475 +0x226

goroutine 129 [IO wait]:
internal/poll.runtime_pollWait(0x18b6b68, 0x72, 0xffffffffffffffff)
/usr/local/Cellar/go/1.12.2/libexec/src/runtime/netpoll.go:182 +0x56
internal/poll.(*pollDesc).wait(0xc000144c18, 0x72, 0x0, 0x1, 0xffffffffffffffff)
/usr/local/Cellar/go/1.12.2/libexec/src/internal/poll/fd_poll_runtime.go:87 +0x9b
internal/poll.(*pollDesc).waitRead(...)
/usr/local/Cellar/go/1.12.2/libexec/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Read(0xc000144c00, 0xc00014bed1, 0x1, 0x1, 0x0, 0x0, 0x0)
/usr/local/Cellar/go/1.12.2/libexec/src/internal/poll/fd_unix.go:169 +0x1f2
net.(*netFD).Read(0xc000144c00, 0xc00014bed1, 0x1, 0x1, 0xc000094a58, 0xc000037768, 0x107069d)
/usr/local/Cellar/go/1.12.2/libexec/src/net/fd_unix.go:202 +0x4f
net.(*conn).Read(0xc000124140, 0xc00014bed1, 0x1, 0x1, 0x0, 0x0, 0x0)
/usr/local/Cellar/go/1.12.2/libexec/src/net/net.go:177 +0x69
net/http.(*connReader).backgroundRead(0xc00014bec0)
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/server.go:677 +0x58
created by net/http.(*connReader).startBackgroundRead
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/server.go:673 +0xca

goroutine 141 [chan receive]:
net/http.(*Transport).getConn.func2.1(0xc0001bc8a0, 0x1727c20, 0x0, 0x0, 0x140958b, 0x4, 0xc00001a2f0, 0xd, 0x0, 0x141ed18)
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/transport.go:981 +0x4a
created by net/http.(*Transport).getConn.func2
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/transport.go:980 +0xfa

goroutine 152 [select]:
net.(*Resolver).lookupIPAddr(0x172f9e0, 0x148d040, 0xc000122ae0, 0x14017bd, 0x3, 0xc0000923f0, 0xa, 0x50, 0x0, 0x0, ...)
/usr/local/Cellar/go/1.12.2/libexec/src/net/lookup.go:275 +0x663
net.(*Resolver).internetAddrList(0x172f9e0, 0x148d040, 0xc000122ae0, 0x14017bd, 0x3, 0xc0000923f0, 0xd, 0x0, 0x0, 0x0, ...)
/usr/local/Cellar/go/1.12.2/libexec/src/net/ipsock.go:280 +0x61f
net.(*Resolver).resolveAddrList(0x172f9e0, 0x148d040, 0xc000122ae0, 0x1401b4e, 0x4, 0x14017bd, 0x3, 0xc0000923f0, 0xd, 0x0, ...)
/usr/local/Cellar/go/1.12.2/libexec/src/net/dial.go:213 +0x508
net.(*Dialer).DialContext(0xc00009e120, 0x148d000, 0xc0000b2048, 0x14017bd, 0x3, 0xc0000923f0, 0xd, 0x0, 0x0, 0x0, ...)
/usr/local/Cellar/go/1.12.2/libexec/src/net/dial.go:395 +0x202
net/http.(*Transport).dial(0x1727c20, 0x148d000, 0xc0000b2048, 0x14017bd, 0x3, 0xc0000923f0, 0xd, 0x0, 0xc0001a0c00, 0xbf289262b0294cc8, ...)
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/transport.go:932 +0x210
net/http.(*Transport).dialConn(0x1727c20, 0x148d000, 0xc0000b2048, 0x0, 0x140958b, 0x4, 0xc0000923f0, 0xd, 0x0, 0x0, ...)
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/transport.go:1259 +0x19d1
net/http.(*Transport).getConn.func4(0x1727c20, 0x148d000, 0xc0000b2048, 0xc0000833e0, 0xc000076ea0)
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/transport.go:1015 +0xa6
created by net/http.(*Transport).getConn
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/transport.go:1014 +0x455

goroutine 126 [chan receive]:
net/http.(*Transport).getConn.func2.1(0xc00017bce0, 0x1727c20, 0x0, 0x0, 0x140958b, 0x4, 0xc000156630, 0xd, 0x0, 0x141ed18)
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/transport.go:981 +0x4a
created by net/http.(*Transport).getConn.func2
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/transport.go:980 +0xfa

goroutine 154 [syscall]:
net._C2func_getaddrinfo(0xc000092410, 0x0, 0xc0000834a0, 0xc0001240f0, 0x0, 0x0, 0x0)
_cgo_gotypes.go:98 +0x55
net.cgoLookupIPCNAME.func1(0xc000092410, 0xb, 0xb, 0xc0000834a0, 0xc0001240f0, 0xa, 0x102d77f, 0x8)
/usr/local/Cellar/go/1.12.2/libexec/src/net/cgo_unix.go:154 +0x13e
net.cgoLookupIPCNAME(0x14017bd, 0x3, 0xc0000923f0, 0xa, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
/usr/local/Cellar/go/1.12.2/libexec/src/net/cgo_unix.go:154 +0x176
net.cgoIPLookup(0xc000122ba0, 0x14017bd, 0x3, 0xc0000923f0, 0xa)
/usr/local/Cellar/go/1.12.2/libexec/src/net/cgo_unix.go:206 +0x67
created by net.cgoLookupIP
/usr/local/Cellar/go/1.12.2/libexec/src/net/cgo_unix.go:216 +0xc7

goroutine 135 [select]:
net.(*sysDialer).dialParallel(0xc000120780, 0x148d040, 0xc000074b40, 0xc000012470, 0x1, 0x1, 0xc000012480, 0x1, 0x1, 0x0, ...)
/usr/local/Cellar/go/1.12.2/libexec/src/net/dial.go:482 +0x323
net.(*Dialer).DialContext(0xc00009e120, 0x148d000, 0xc0000b2048, 0x14017bd, 0x3, 0xc00001a2f0, 0xd, 0x0, 0x0, 0x0, ...)
/usr/local/Cellar/go/1.12.2/libexec/src/net/dial.go:415 +0x4f5
net/http.(*Transport).dial(0x1727c20, 0x148d000, 0xc0000b2048, 0x14017bd, 0x3, 0xc00001a2f0, 0xd, 0x0, 0xc000174600, 0xbf28926270282bb8, ...)
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/transport.go:932 +0x210
net/http.(*Transport).dialConn(0x1727c20, 0x148d000, 0xc0000b2048, 0x0, 0x140958b, 0x4, 0xc00001a2f0, 0xd, 0x0, 0x2, ...)
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/transport.go:1259 +0x19d1
net/http.(*Transport).getConn.func4(0x1727c20, 0x148d000, 0xc0000b2048, 0xc00011ec60, 0xc0001bc8a0)
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/transport.go:1015 +0xa6
created by net/http.(*Transport).getConn
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/transport.go:1014 +0x455

goroutine 144 [select]:
net.(*Resolver).lookupIPAddr(0x172f9e0, 0x148d040, 0xc0000751a0, 0x14017bd, 0x3, 0xc00001a410, 0xa, 0x50, 0x0, 0x0, ...)
/usr/local/Cellar/go/1.12.2/libexec/src/net/lookup.go:275 +0x663
net.(*Resolver).internetAddrList(0x172f9e0, 0x148d040, 0xc0000751a0, 0x14017bd, 0x3, 0xc00001a410, 0xd, 0x0, 0x0, 0x0, ...)
/usr/local/Cellar/go/1.12.2/libexec/src/net/ipsock.go:280 +0x61f
net.(*Resolver).resolveAddrList(0x172f9e0, 0x148d040, 0xc0000751a0, 0x1401b4e, 0x4, 0x14017bd, 0x3, 0xc00001a410, 0xd, 0x0, ...)
/usr/local/Cellar/go/1.12.2/libexec/src/net/dial.go:213 +0x508
net.(*Dialer).DialContext(0xc00009e120, 0x148d000, 0xc0000b2048, 0x14017bd, 0x3, 0xc00001a410, 0xd, 0x0, 0x0, 0x0, ...)
/usr/local/Cellar/go/1.12.2/libexec/src/net/dial.go:395 +0x202
net/http.(*Transport).dial(0x1727c20, 0x148d000, 0xc0000b2048, 0x14017bd, 0x3, 0xc00001a410, 0xd, 0x0, 0xc000174900, 0xbf289262f0298b48, ...)
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/transport.go:932 +0x210
net/http.(*Transport).dialConn(0x1727c20, 0x148d000, 0xc0000b2048, 0x0, 0x140958b, 0x4, 0xc00001a410, 0xd, 0x0, 0x107069d, ...)
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/transport.go:1259 +0x19d1
net/http.(*Transport).getConn.func4(0x1727c20, 0x148d000, 0xc0000b2048, 0xc00011f080, 0xc0001bce40)
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/transport.go:1015 +0xa6
created by net/http.(*Transport).getConn
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/transport.go:1014 +0x455

goroutine 120 [chan receive]:
net/http.(*Transport).getConn.func2.1(0xc000076ea0, 0x1727c20, 0x0, 0x0, 0x140958b, 0x4, 0xc0000923f0, 0xd, 0x0, 0x141ed18)
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/transport.go:981 +0x4a
created by net/http.(*Transport).getConn.func2
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/transport.go:980 +0xfa

goroutine 194 [select]:
net/http.setRequestCancel.func3(0x0, 0xc000244060, 0xc000150eb0, 0xc0001566dc, 0xc00017bf20)
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/client.go:321 +0xcf
created by net/http.setRequestCancel
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/client.go:320 +0x251

goroutine 121 [chan receive]:
net/http.(*Transport).getConn.func2.1(0xc0001bce40, 0x1727c20, 0x0, 0x0, 0x140958b, 0x4, 0xc00001a410, 0xd, 0x0, 0x141ed18)
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/transport.go:981 +0x4a
created by net/http.(*Transport).getConn.func2
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/transport.go:980 +0xfa

goroutine 195 [select]:
net.(*Resolver).lookupIPAddr(0x172f9e0, 0x148d040, 0xc00015bb00, 0x14017bd, 0x3, 0xc0001566f0, 0xa, 0x50, 0x0, 0x0, ...)
/usr/local/Cellar/go/1.12.2/libexec/src/net/lookup.go:275 +0x663
net.(*Resolver).internetAddrList(0x172f9e0, 0x148d040, 0xc00015bb00, 0x14017bd, 0x3, 0xc0001566f0, 0xd, 0x0, 0x0, 0x0, ...)
/usr/local/Cellar/go/1.12.2/libexec/src/net/ipsock.go:280 +0x61f
net.(*Resolver).resolveAddrList(0x172f9e0, 0x148d040, 0xc00015bb00, 0x1401b4e, 0x4, 0x14017bd, 0x3, 0xc0001566f0, 0xd, 0x0, ...)
/usr/local/Cellar/go/1.12.2/libexec/src/net/dial.go:213 +0x508
net.(*Dialer).DialContext(0xc00009e120, 0x148d000, 0xc0000b2048, 0x14017bd, 0x3, 0xc0001566f0, 0xd, 0x0, 0x0, 0x0, ...)
/usr/local/Cellar/go/1.12.2/libexec/src/net/dial.go:395 +0x202
net/http.(*Transport).dial(0x1727c20, 0x148d000, 0xc0000b2048, 0x14017bd, 0x3, 0xc0001566f0, 0xd, 0x0, 0xc000187800, 0xbf289264302ea3f8, ...)
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/transport.go:932 +0x210
net/http.(*Transport).dialConn(0x1727c20, 0x148d000, 0xc0000b2048, 0x0, 0x140958b, 0x4, 0xc0001566f0, 0xd, 0x0, 0x0, ...)
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/transport.go:1259 +0x19d1
net/http.(*Transport).getConn.func4(0x1727c20, 0x148d000, 0xc0000b2048, 0xc0002440c0, 0xc00017bf80)
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/transport.go:1015 +0xa6
created by net/http.(*Transport).getConn
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/transport.go:1014 +0x455

goroutine 124 [select]:
net.(*Resolver).lookupIPAddr(0x172f9e0, 0x148d040, 0xc00015b860, 0x14017bd, 0x3, 0xc000156630, 0xa, 0x50, 0x0, 0x0, ...)
/usr/local/Cellar/go/1.12.2/libexec/src/net/lookup.go:275 +0x663
net.(*Resolver).internetAddrList(0x172f9e0, 0x148d040, 0xc00015b860, 0x14017bd, 0x3, 0xc000156630, 0xd, 0x0, 0x0, 0x0, ...)
/usr/local/Cellar/go/1.12.2/libexec/src/net/ipsock.go:280 +0x61f
net.(*Resolver).resolveAddrList(0x172f9e0, 0x148d040, 0xc00015b860, 0x1401b4e, 0x4, 0x14017bd, 0x3, 0xc000156630, 0xd, 0x0, ...)
/usr/local/Cellar/go/1.12.2/libexec/src/net/dial.go:213 +0x508
net.(*Dialer).DialContext(0xc00009e120, 0x148d000, 0xc0000b2048, 0x14017bd, 0x3, 0xc000156630, 0xd, 0x0, 0x0, 0x0, ...)
/usr/local/Cellar/go/1.12.2/libexec/src/net/dial.go:395 +0x202
net/http.(*Transport).dial(0x1727c20, 0x148d000, 0xc0000b2048, 0x14017bd, 0x3, 0xc000156630, 0xd, 0x0, 0xc000187500, 0xbf28926370322a50, ...)
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/transport.go:932 +0x210
net/http.(*Transport).dialConn(0x1727c20, 0x148d000, 0xc0000b2048, 0x0, 0x140958b, 0x4, 0xc000156630, 0xd, 0x0, 0x0, ...)
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/transport.go:1259 +0x19d1
net/http.(*Transport).getConn.func4(0x1727c20, 0x148d000, 0xc0000b2048, 0xc00014bce0, 0xc00017bce0)
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/transport.go:1015 +0xa6
created by net/http.(*Transport).getConn
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/transport.go:1014 +0x455

goroutine 139 [select]:
net.(*netFD).connect.func2(0x148cfc0, 0xc00005a7c0, 0xc000120800, 0xc0001bcc60, 0xc0001bcc00)
/usr/local/Cellar/go/1.12.2/libexec/src/net/fd_unix.go:129 +0xba
created by net.(*netFD).connect
/usr/local/Cellar/go/1.12.2/libexec/src/net/fd_unix.go:128 +0x25a

goroutine 125 [chan receive]:
net/http.(*Transport).getConn.func2.1(0xc0001bd0e0, 0x1727c20, 0x0, 0x0, 0x140958b, 0x4, 0xc00001a470, 0xd, 0x0, 0x141ed18)
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/transport.go:981 +0x4a
created by net/http.(*Transport).getConn.func2
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/transport.go:980 +0xfa

goroutine 163 [select]:
net.(*Resolver).lookupIPAddr(0x172f9e0, 0x148d040, 0xc000075560, 0x14017bd, 0x3, 0xc00001a470, 0xa, 0x50, 0x0, 0x0, ...)
/usr/local/Cellar/go/1.12.2/libexec/src/net/lookup.go:275 +0x663
net.(*Resolver).internetAddrList(0x172f9e0, 0x148d040, 0xc000075560, 0x14017bd, 0x3, 0xc00001a470, 0xd, 0x0, 0x0, 0x0, ...)
/usr/local/Cellar/go/1.12.2/libexec/src/net/ipsock.go:280 +0x61f
net.(*Resolver).resolveAddrList(0x172f9e0, 0x148d040, 0xc000075560, 0x1401b4e, 0x4, 0x14017bd, 0x3, 0xc00001a470, 0xd, 0x0, ...)
/usr/local/Cellar/go/1.12.2/libexec/src/net/dial.go:213 +0x508
net.(*Dialer).DialContext(0xc00009e120, 0x148d000, 0xc0000b2048, 0x14017bd, 0x3, 0xc00001a470, 0xd, 0x0, 0x0, 0x0, ...)
/usr/local/Cellar/go/1.12.2/libexec/src/net/dial.go:395 +0x202
net/http.(*Transport).dial(0x1727c20, 0x148d000, 0xc0000b2048, 0x14017bd, 0x3, 0xc00001a470, 0xd, 0x0, 0xc000174b00, 0xbf2892633036b660, ...)
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/transport.go:932 +0x210
net/http.(*Transport).dialConn(0x1727c20, 0x148d000, 0xc0000b2048, 0x0, 0x140958b, 0x4, 0xc00001a470, 0xd, 0x0, 0x0, ...)
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/transport.go:1259 +0x19d1
net/http.(*Transport).getConn.func4(0x1727c20, 0x148d000, 0xc0000b2048, 0xc00011f320, 0xc0001bd0e0)
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/transport.go:1015 +0xa6
created by net/http.(*Transport).getConn
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/transport.go:1014 +0x455

goroutine 178 [select]:
net/http.(*Transport).getConn(0x1727c20, 0xc000244090, 0x0, 0x140958b, 0x4, 0xc0001566f0, 0xd, 0x0, 0x0, 0x0, ...)
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/transport.go:1020 +0x63d
net/http.(*Transport).roundTrip(0x1727c20, 0xc000187900, 0xc000244060, 0xc0001566dc, 0xc0001566e0)
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/transport.go:467 +0x6ef
net/http.(*Transport).RoundTrip(0x1727c20, 0xc000187900, 0x1727c20, 0xbf289264302ea3f8, 0x6f223291f)
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/roundtrip.go:17 +0x35
net/http.send(0xc000187800, 0x1486160, 0x1727c20, 0xbf289264302ea3f8, 0x6f223291f, 0x172ff00, 0xc00014c180, 0xbf289264302ea3f8, 0x1, 0x0)
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/client.go:250 +0x461
net/http.(*Client).send(0xc00011e270, 0xc000187800, 0xbf289264302ea3f8, 0x6f223291f, 0x172ff00, 0xc00014c180, 0x0, 0x1, 0xc000064c00)
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/client.go:174 +0xfb
net/http.(*Client).do(0xc00011e270, 0xc000187800, 0x0, 0x0, 0x0)
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/client.go:641 +0x279
net/http.(*Client).Do(...)
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/client.go:509
main.basicHandler(0x148c8c0, 0xc000180540, 0xc000187700)
/Users/emily/Desktop/main.go:52 +0xce
net/http.HandlerFunc.ServeHTTP(0x141e968, 0x148c8c0, 0xc000180540, 0xc000187700)
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/server.go:1994 +0x44
net/http.(*ServeMux).ServeHTTP(0xc00005a0c0, 0x148c8c0, 0xc000180540, 0xc000187700)
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/server.go:2374 +0x1d6
net/http.serverHandler.ServeHTTP(0xc0001261a0, 0x148c8c0, 0xc000180540, 0xc000187700)
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/server.go:2773 +0xa8
net/http.(*conn).serve(0xc0001d2640, 0x148cfc0, 0xc000148dc0)
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/server.go:1877 +0x851
created by net/http.(*Server).Serve
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/server.go:2883 +0x2f4

goroutine 128 [chan receive]:
net/http.(*Transport).getConn.func2.1(0xc0000771a0, 0x1727c20, 0x0, 0x0, 0x140958b, 0x4, 0xc0000924d0, 0xd, 0x0, 0x141ed18)
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/transport.go:981 +0x4a
created by net/http.(*Transport).getConn.func2
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/transport.go:980 +0xfa

goroutine 158 [select]:
net.(*Resolver).lookupIPAddr(0x172f9e0, 0x148d040, 0xc0001231a0, 0x14017bd, 0x3, 0xc0000924d0, 0xa, 0x50, 0x0, 0x0, ...)
/usr/local/Cellar/go/1.12.2/libexec/src/net/lookup.go:275 +0x663
net.(*Resolver).internetAddrList(0x172f9e0, 0x148d040, 0xc0001231a0, 0x14017bd, 0x3, 0xc0000924d0, 0xd, 0x0, 0x0, 0x0, ...)
/usr/local/Cellar/go/1.12.2/libexec/src/net/ipsock.go:280 +0x61f
net.(*Resolver).resolveAddrList(0x172f9e0, 0x148d040, 0xc0001231a0, 0x1401b4e, 0x4, 0x14017bd, 0x3, 0xc0000924d0, 0xd, 0x0, ...)
/usr/local/Cellar/go/1.12.2/libexec/src/net/dial.go:213 +0x508
net.(*Dialer).DialContext(0xc00009e120, 0x148d000, 0xc0000b2048, 0x14017bd, 0x3, 0xc0000924d0, 0xd, 0x0, 0x0, 0x0, ...)
/usr/local/Cellar/go/1.12.2/libexec/src/net/dial.go:395 +0x202
net/http.(*Transport).dial(0x1727c20, 0x148d000, 0xc0000b2048, 0x14017bd, 0x3, 0xc0000924d0, 0xd, 0x0, 0xc0001a1100, 0xbf289263b03f2688, ...)
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/transport.go:932 +0x210
net/http.(*Transport).dialConn(0x1727c20, 0x148d000, 0xc0000b2048, 0x0, 0x140958b, 0x4, 0xc0000924d0, 0xd, 0x0, 0x0, ...)
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/transport.go:1259 +0x19d1
net/http.(*Transport).getConn.func4(0x1727c20, 0x148d000, 0xc0000b2048, 0xc000083800, 0xc0000771a0)
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/transport.go:1015 +0xa6
created by net/http.(*Transport).getConn
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/transport.go:1014 +0x455

goroutine 113 [chan receive]:
net/http.(*Transport).getConn.func2.1(0xc000077440, 0x1727c20, 0x0, 0x0, 0x140958b, 0x4, 0xc000092530, 0xd, 0x0, 0x141ed18)
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/transport.go:981 +0x4a
created by net/http.(*Transport).getConn.func2
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/transport.go:980 +0xfa

goroutine 161 [select]:
net.(*Resolver).lookupIPAddr(0x172f9e0, 0x148d040, 0xc000123680, 0x14017bd, 0x3, 0xc000092530, 0xa, 0x50, 0x0, 0x0, ...)
/usr/local/Cellar/go/1.12.2/libexec/src/net/lookup.go:275 +0x663
net.(*Resolver).internetAddrList(0x172f9e0, 0x148d040, 0xc000123680, 0x14017bd, 0x3, 0xc000092530, 0xd, 0x0, 0x0, 0x0, ...)
/usr/local/Cellar/go/1.12.2/libexec/src/net/ipsock.go:280 +0x61f
net.(*Resolver).resolveAddrList(0x172f9e0, 0x148d040, 0xc000123680, 0x1401b4e, 0x4, 0x14017bd, 0x3, 0xc000092530, 0xd, 0x0, ...)
/usr/local/Cellar/go/1.12.2/libexec/src/net/dial.go:213 +0x508
net.(*Dialer).DialContext(0xc00009e120, 0x148d000, 0xc0000b2048, 0x14017bd, 0x3, 0xc000092530, 0xd, 0x0, 0x0, 0x0, ...)
/usr/local/Cellar/go/1.12.2/libexec/src/net/dial.go:395 +0x202
net/http.(*Transport).dial(0x1727c20, 0x148d000, 0xc0000b2048, 0x14017bd, 0x3, 0xc000092530, 0xd, 0x0, 0xc0001a1300, 0xbf289263f02f6360, ...)
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/transport.go:932 +0x210
net/http.(*Transport).dialConn(0x1727c20, 0x148d000, 0xc0000b2048, 0x0, 0x140958b, 0x4, 0xc000092530, 0xd, 0x0, 0x1485da0, ...)
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/transport.go:1259 +0x19d1
net/http.(*Transport).getConn.func4(0x1727c20, 0x148d000, 0xc0000b2048, 0xc000083a70, 0xc000077440)
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/transport.go:1015 +0xa6
created by net/http.(*Transport).getConn
/usr/local/Cellar/go/1.12.2/libexec/src/net/http/transport.go:1014 +0x455

rax 0x104
rbx 0x4600
rcx 0x7fff5fbff4d8
rdx 0x4600
rdi 0x1730d08
rsi 0x460100004700
rbp 0x7fff5fbff570
rsp 0x7fff5fbff4d8
r8 0x0
r9 0x60
r10 0x0
r11 0x202
r12 0x1730d08
r13 0x16
r14 0x1
r15 0x7fffda13e3c0
rip 0x7fffd134abf2
rflags 0x203
cs 0x7
fs 0x0
gs 0x0
exit status 2

I'm curious why the goroutines continue to go up. Is there a specific timeout that should force kill them? Do they only drop off when garbage collections occurs? Messing with the transport settings hasn't changed the behavior at all. Nor has canceling the context. According to the docs I've read, I have checked the boxes on how to gracefully handle Network glitches, but that obviously doesn't seem to be the case!

@ianlancetaylor

This comment has been minimized.

Copy link
Contributor

commented Apr 26, 2019

Garbage collection does not affect the number of goroutines.

I don't see all that many goroutines in the ^\ dump. Those goroutines seem to be mostly waiting on network I/O one way or another. When you say that the number of goroutines goes up, how many are we talking about?

@esuhadolnik

This comment has been minimized.

Copy link
Author

commented Apr 26, 2019

When running locally with 1TPS I see the goroutines go as high as 140 before dropping off.

@bradfitz

This comment has been minimized.

Copy link
Member

commented Apr 26, 2019

Which goroutines?

You can also get it with https://golang.org/pkg/runtime/#Stack and all=true.

@ianlancetaylor

This comment has been minimized.

Copy link
Contributor

commented Apr 26, 2019

Note that while 140 may be a lot of goroutines for your program, it's not a lot for Go in general. Go programs can easily support thousands of goroutines.

@maazghani

This comment has been minimized.

Copy link

commented Apr 29, 2019

@bradfitz I saw some discussions in other issues of a potential way to get debug output for http1 the way GODEBUG=http2debug=2 is supported. From your experience is that worthwhile cherry-picking to troubleshoot or are most of the beneficial debug output only available in http2? Sorry somewhat ancillary to the main post, but related to troubleshooting the same issue.

@esuhadolnik

This comment has been minimized.

Copy link
Author

commented May 1, 2019

I haven't dug into the runtime stack quite yet (I'll get to that in just a bit), but I wanted to share it here anyways: goroutine_stack.txt

I know 140 isn't a ton of goroutines, but I'm more curious about the behavior of the goroutines climbing and climbing and then suddenly dropping off back down to 3 or 5. Then a second later, starting to climb again.

I am also curious if there is more of a context cancelation that can be done so the goroutine climb doesn't happen at all?

On a production server I have seen this happen for a longer period of time, where the goroutines climb and queue so much that CPU begins to drop, requests are no longer served, and the requests that are queued are obviously taking a long time to finish. There is no smoking gun as to what causes it, which is why we've begun looking into network issues.

As it is probably expected behavior, I would love to know if there is a way to mitigate it's impact or if there are any best practices for handling network glitches besides using server side and HTTP client side timeouts as well as specific transport settings.

@bradfitz bradfitz added NeedsFix and removed WaitingForInfo labels May 1, 2019

@bradfitz bradfitz changed the title goroutines climb when network issue occurs and then suddenly drop off net/http: Client.Timeout is not propagated to Request's Context Deadline May 1, 2019

@bradfitz

This comment has been minimized.

Copy link
Member

commented May 1, 2019

Thanks for the dump. That showed the problem: the DNS lookups (via conn dials) are blocked for a long time, which means the Client.Timeout value isn't being propagated down to the dials.

A little test added to net/http/client_test.go confirms:

func TestClientPropagatesTimeoutToContext(t *testing.T) {
        errDial := errors.New("not actually dialing")
        c := &Client{
                Timeout: 5 * time.Second,
                Transport: &Transport{
                        DialContext: func(ctx context.Context, netw, addr string) (net.Conn, error) {
                                deadline, ok := ctx.Deadline()
                                if !ok {
                                        t.Error("no deadline")
                                } else {
                                        t.Errorf("deadling in %v", deadline.Sub(time.Now()).Round(time.Second/10))
                                }
                                return nil, errDial
                        },
                },
        }
        c.Get("https://example.tld/")
}

Currently fails with:

$ go test -short -run=TestClientPropagatesTimeoutToContext -v
=== RUN   TestClientPropagatesTimeoutToContext
--- FAIL: TestClientPropagatesTimeoutToContext (0.00s)
    client_test.go:1925: no deadline
FAIL
exit status 1
FAIL    net/http        0.278s

Fix seems simple enough.

Thanks for the report.

@bradfitz bradfitz self-assigned this May 1, 2019

@bradfitz bradfitz added this to the Go1.13 milestone May 1, 2019

@esuhadolnik

This comment has been minimized.

Copy link
Author

commented May 1, 2019

Thank you, Brad. Curious, do you have any recommendations on mitigation for the time being until the 1.13 release?

@bradfitz

This comment has been minimized.

Copy link
Member

commented May 1, 2019

One workaround for now is to use Request.WithContext to set a Request's Context to include a timeout (with context.WithTimeout) and then you don't need to use the old pre-context Client.Timeout.

@gopherbot

This comment has been minimized.

Copy link

commented May 7, 2019

Change https://golang.org/cl/175857 mentions this issue: net/http: propagate Client.Timeout down into Request's context deadline

@bradfitz

This comment has been minimized.

Copy link
Member

commented May 7, 2019

I sent a CL for this but I don't think it's important enough given the (non-zero) risk for Go 1.13, so I'm going to mark this for Go 1.14. Go 1.14 will also have http.NewRequestWithContext to make using contexts a bit easier.

@bradfitz bradfitz modified the milestones: Go1.13, Go1.14 May 7, 2019

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.