Goroutine/client leak stemming from GCS client usage

[jameshartig]

This seems very similar to #2251 which I filed 7 years ago.

What version of gRPC are you using?

v1.77.0 and v1.78.0

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

go1.25.6 linux/amd64

What operating system (Linux, Windows, …) and version?

CentOS running in GCP

What did you do?

For some background, the service receives a Pub/Sub message every 25th minute of the hour via a configured Cloud Scheduler job, this job compresses some files from another system and uploads the resulting tar file to a new file in a GCS bucket using the Object(...).NewWriter(ctx) function. The largest affected VM is in us-central1-f and the bucket is in us. I believe this makes it a candidate for Direct Connectivity but I haven't verified.

We previously used the XML (default) API in the Go client but recently switched over to the GRPC client (using storage.NewGRPCClient) which was deployed on 2/6 at 4:12 PM UTC.

We have telemetry that records when Close is called on the underlying ObjectWriter and we see it being called within a few seconds after opening the file.

This is actually one of our last remaining services that uses Synchronous: true, in case that's relevant. The Pub/Sub subscription is created with:

MaxOutstandingBytes: -1
MaxExtension: 30 * time.Minute
Synchronous: true
NumGoroutines: 1
MaxOutstandingMessages: 1

Our receiver callback finishes without error after 3-5 seconds. At that point we continue to see the number of grpc-related goroutines go up until 30 minutes (which is maybe related to the above MaxExtension value).

There was a small but (seemingly) bounded increase when we switched to the new GRPC client as you can see from this graph of open FDs for the affected service:

but it started to become an issue on 2/6 at 4:30am UTC:

cloud.google.com/go has been at v0.123.0 before and after the increase. cloud.google.com/go/pubsub has been at v1.50.1 before and after the increase.
google.golang.org/grpc did change from v1.77.0 to v1.78.0 for but not until 2/6 at 12:25pm UTC.
cloud.google.com/go/storage changed from v1.58.0 to v1.59.2 but again, not until 2/6 at 12:25pm UTC.

We can't find any changes/deploys/etc around the larger increase so we believe this is caused by something server-side or potentially network-related.

What did you expect to see?

I expected to see the file descriptors stay bounded, especially when the client is idle.

What did you see instead?

Instead we see a massive goroutine/socket leak until 30 minutes has passed since receiving the pub/sub message. Given the goroutine dump includes 427 goroutines in resetTransportAndUnlock I think it has something to do with failing to connect and continuously retrying but not closing the old connection somehow?

Running ss -antep | grep PID shows all connections to Google IPs:

ESTAB      0      0      10.212.0.7:40918              34.126.9.158:10457               users:(("seaweed-backupe",pid=14363,fd=1688)) timer:(keepalive,2.835ms,0) uid:1002 ino:3093432626 sk:ffff9b80de76b640 <->          [894/894]
ESTAB      0      0      10.212.0.7:14318              34.126.8.42:11038               users:(("seaweed-backupe",pid=14363,fd=348)) timer:(keepalive,4.755ms,0) uid:1002 ino:3093425890 sk:ffff9b815be93e00 <->
ESTAB      0      0      10.212.0.7:13810              34.126.10.53:10201               users:(("seaweed-backupe",pid=14363,fd=2794)) timer:(keepalive,11sec,0) uid:1002 ino:3093413000 sk:ffff9b81b8b69f00 <->
ESTAB      0      0      10.212.0.7:33525              34.126.8.42:10658               users:(("seaweed-backupe",pid=14363,fd=2921)) timer:(keepalive,5.523ms,0) uid:1002 ino:3093415002 sk:ffff9b82317b26c0 <->
ESTAB      0      0      10.212.0.7:52737              34.126.9.143:10154               users:(("seaweed-backupe",pid=14363,fd=1656)) timer:(keepalive,14sec,0) uid:1002 ino:3093431071 sk:ffff9b8246631740 <->
ESTAB      0      0      10.212.0.7:15785              34.126.8.144:10185               users:(("seaweed-backupe",pid=14363,fd=1760)) timer:(keepalive,13sec,0) uid:1002 ino:3093423816 sk:ffff9b815643dd00 <->
ESTAB      0      0      10.212.0.7:11111              34.126.9.23:10650               users:(("seaweed-backupe",pid=14363,fd=3332)) timer:(keepalive,14sec,0) uid:1002 ino:3093421813 sk:ffff9b8044f32e80 <->
ESTAB      0      0      10.212.0.7:44134              34.126.9.143:10120               users:(("seaweed-backupe",pid=14363,fd=3873)) timer:(keepalive,1.619ms,0) uid:1002 ino:3093414380 sk:ffff9b8191309740 <->
ESTAB      0      0      10.212.0.7:36233              34.126.9.158:10854               users:(("seaweed-backupe",pid=14363,fd=698)) timer:(keepalive,3.027ms,0) uid:1002 ino:3093421973 sk:ffff9b8052a0ae80 <->
ESTAB      0      0      10.212.0.7:57440              34.126.9.158:11100               users:(("seaweed-backupe",pid=14363,fd=2097)) timer:(keepalive,10sec,0) uid:1002 ino:3093431516 sk:ffff9b81913a0000 <->
ESTAB      0      0      10.212.0.7:36941              34.126.9.158:11159               users:(("seaweed-backupe",pid=14363,fd=3704)) timer:(keepalive,1.171ms,0) uid:1002 ino:3093413578 sk:ffff9b819123b640 <->
ESTAB      0      0      10.212.0.7:36241              34.126.8.42:10260               users:(("seaweed-backupe",pid=14363,fd=2963)) timer:(keepalive,6.099ms,0) uid:1002 ino:3093433376 sk:ffff9b81fee6ae80 <->
ESTAB      0      0      10.212.0.7:20275              34.126.8.144:10185               users:(("seaweed-backupe",pid=14363,fd=2287)) timer:(keepalive,6.803ms,0) uid:1002 ino:3093434860 sk:ffff9b82317b45c0 <->
ESTAB      0      0      10.212.0.7:27623              34.126.8.144:10215               users:(("seaweed-backupe",pid=14363,fd=2374)) timer:(keepalive,7.313ms,0) uid:1002 ino:3093418569 sk:ffff9b81e6b1cd80 <->
ESTAB      0      0      10.212.0.7:59286              34.126.9.143:10192               users:(("seaweed-backupe",pid=14363,fd=2157)) timer:(keepalive,13sec,0) uid:1002 ino:3093413800 sk:ffff9b8141828000 <->
ESTAB      0      0      10.212.0.7:25709              34.126.10.53:10183               users:(("seaweed-backupe",pid=14363,fd=3596)) timer:(keepalive,849ms,0) uid:1002 ino:3093413473 sk:ffff9b820c450f80 <->
ESTAB      0      0      10.212.0.7:15517              34.126.8.142:10442               users:(("seaweed-backupe",pid=14363,fd=2569)) timer:(keepalive,081ms,0) uid:1002 ino:3093431993 sk:ffff9b8273e1f440 <->
ESTAB      0      0      10.212.0.7:26899              34.126.8.146:10734               users:(("seaweed-backupe",pid=14363,fd=625)) timer:(keepalive,913ms,0) uid:1002 ino:3093419454 sk:ffff9b80fcba26c0 <->
ESTAB      0      0      10.212.0.7:54312              34.126.10.53:10204               users:(("seaweed-backupe",pid=14363,fd=3566)) timer:(keepalive,721ms,0) uid:1002 ino:3093413443 sk:ffff9b80dde507c0 <->
ESTAB      0      0      10.212.0.7:48472              34.126.10.53:10273               users:(("seaweed-backupe",pid=14363,fd=3942)) timer:(keepalive,1.425ms,0) uid:1002 ino:3093426377 sk:ffff9b809be826c0 <->
ESTAB      0      0      10.212.0.7:55020              34.126.8.146:10185               users:(("seaweed-backupe",pid=14363,fd=3160)) timer:(keepalive,1.233ms,0) uid:1002 ino:3093419474 sk:ffff9b80fcba5d00 <->
ESTAB      0      0      10.212.0.7:17040              34.126.4.142:17220               users:(("seaweed-backupe",pid=14363,fd=123)) timer:(keepalive,14sec,0) uid:1002 ino:3093425806 sk:ffff9b81b8a49f00 <->
ESTAB      0      0      10.212.0.7:55532              34.126.8.144:10281               users:(("seaweed-backupe",pid=14363,fd=2193)) timer:(keepalive,2.641ms,0) uid:1002 ino:3093414411 sk:ffff9b82317f3640 <->
ESTAB      0      0      10.212.0.7:36028              34.126.8.144:22059               users:(("seaweed-backupe",pid=14363,fd=34)) timer:(keepalive,14sec,0) uid:1002 ino:3093426818 sk:ffff9b826efa8000 <->
ESTAB      0      0      10.212.0.7:44286              34.126.9.143:10120               users:(("seaweed-backupe",pid=14363,fd=3087)) timer:(keepalive,4.753ms,0) uid:1002 ino:3093414439 sk:ffff9b8141999f00 <->
ESTAB      0      0      10.212.0.7:47129              34.126.8.42:10972               users:(("seaweed-backupe",pid=14363,fd=955)) timer:(keepalive,13sec,0) uid:1002 ino:3093426209 sk:ffff9b8246637440 <->
ESTAB      0      0      10.212.0.7:15068              34.126.8.144:10213               users:(("seaweed-backupe",pid=14363,fd=2395)) timer:(keepalive,273ms,0) uid:1002 ino:3093421838 sk:ffff9b81fb24ae80 <->
ESTAB      0      0      10.212.0.7:21232              34.126.9.158:10738               users:(("seaweed-backupe",pid=14363,fd=360)) timer:(keepalive,5.393ms,0) uid:1002 ino:3093425900 sk:ffff9b80dbacf440 <->
ESTAB      0      0      10.212.0.7:29546              34.126.10.53:10321               users:(("seaweed-backupe",pid=14363,fd=2733)) timer:(keepalive,2.961ms,0) uid:1002 ino:3093413080 sk:ffff9b8246d7be00 <->
ESTAB      0      0      10.212.0.7:31658              34.126.8.144:10316               users:(("seaweed-backupe",pid=14363,fd=811)) timer:(keepalive,14sec,0) uid:1002 ino:3093421819 sk:ffff9b80d7dfb640 <->
ESTAB      0      0      10.212.0.7:10775              34.126.9.158:11326               users:(("seaweed-backupe",pid=14363,fd=4062)) timer:(keepalive,1.745ms,0) uid:1002 ino:3093425546 sk:ffff9b81b8b98f80 <->
ESTAB      0      0      10.212.0.7:54951              34.126.8.45:10016               users:(("seaweed-backupe",pid=14363,fd=2532)) timer:(keepalive,10sec,0) uid:1002 ino:3093421438 sk:ffff9b819edc5540 <->
ESTAB      0      0      10.212.0.7:14099              34.126.9.23:10333               users:(("seaweed-backupe",pid=14363,fd=3217)) timer:(keepalive,14sec,0) uid:1002 ino:3093421818 sk:ffff9b80ca14b640 <->
ESTAB      0      0      10.212.0.7:34007              34.126.10.53:10123               users:(("seaweed-backupe",pid=14363,fd=1958)) timer:(keepalive,1.425ms,0) uid:1002 ino:3093425436 sk:ffff9b8273ff8f80 <->
ESTAB      0      0      10.212.0.7:48326              34.126.8.42:10531               users:(("seaweed-backupe",pid=14363,fd=3270)) timer:(keepalive,4.241ms,0) uid:1002 ino:3093417580 sk:ffff9b80dba3b640 <->
ESTAB      0      0      10.212.0.7:31899              34.126.8.144:10027               users:(("seaweed-backupe",pid=14363,fd=2203)) timer:(keepalive,2.449ms,0) uid:1002 ino:3093414117 sk:ffff9b82057b5d00 <->
ESTAB      0      0      10.212.0.7:24434              34.126.9.158:11030               users:(("seaweed-backupe",pid=14363,fd=383)) timer:(keepalive,7.121ms,0) uid:1002 ino:3093426718 sk:ffff9b81a41af440 <->
ESTAB      0      0      10.212.0.7:29844              34.126.8.144:22015               users:(("seaweed-backupe",pid=14363,fd=150)) timer:(keepalive,3.601ms,0) uid:1002 ino:3093427524 sk:ffff9b817a7ea6c0 <->
ESTAB      0      0      10.212.0.7:39746              34.126.8.45:10065               users:(("seaweed-backupe",pid=14363,fd=1207)) timer:(keepalive,10sec,0) uid:1002 ino:3093421426 sk:ffff9b8191228f80 <->
ESTAB      0      0      10.212.0.7:30276              34.126.9.158:10608               users:(("seaweed-backupe",pid=14363,fd=4074)) timer:(keepalive,1.745ms,0) uid:1002 ino:3093425558 sk:ffff9b81494db640 <->
ESTAB      0      0      10.212.0.7:14128              34.126.9.143:10278               users:(("seaweed-backupe",pid=14363,fd=1894)) timer:(keepalive,241ms,0) uid:1002 ino:3093433244 sk:ffff9b81c3e64d80 <->
ESTAB      0      0      10.212.0.7:36759              34.126.9.143:10199               users:(("seaweed-backupe",pid=14363,fd=1662)) timer:(keepalive,8.849ms,0) uid:1002 ino:3093432765 sk:ffff9b81a41a9f00 <->
ESTAB      0      0      10.212.0.7:19750              34.126.8.142:10912               users:(("seaweed-backupe",pid=14363,fd=373)) timer:(keepalive,6.289ms,0) uid:1002 ino:3093425910 sk:ffff9b820e354d80 <->
ESTAB      0      0      10.212.0.7:35032              34.126.4.142:17240               users:(("seaweed-backupe",pid=14363,fd=158)) timer:(keepalive,6.545ms,0) uid:1002 ino:3093427792 sk:ffff9b80bb90b640 <->
ESTAB      0      0      10.212.0.7:13599              34.126.8.42:10512               users:(("seaweed-backupe",pid=14363,fd=3264)) timer:(keepalive,1.297ms,0) uid:1002 ino:3093419478 sk:ffff9b80fcba1740 <->
ESTAB      0      0      10.212.0.7:25538              34.126.9.143:10243               users:(("seaweed-backupe",pid=14363,fd=3054)) timer:(keepalive,13sec,0) uid:1002 ino:3093415158 sk:ffff9b80ca21b640 <->
ESTAB      0      0      10.212.0.7:41269              34.126.8.42:10503               users:(("seaweed-backupe",pid=14363,fd=1453)) timer:(keepalive,10sec,0) uid:1002 ino:3093432217 sk:ffff9b81b4788f80 <->
(output truncated)

Goroutine pprof profile:

4046 @ 0x4833ae 0x45f9b7 0x8bfe48 0x8c0618 0x8ca292 0x48bca1
#	0x8bfe47	google.golang.org/grpc/internal/transport.(*controlBuffer).get+0x107	google.golang.org/grpc@v1.78.0/internal/transport/controlbuf.go:425
#	0x8c0617	google.golang.org/grpc/internal/transport.(*loopyWriter).run+0x77	google.golang.org/grpc@v1.78.0/internal/transport/controlbuf.go:602
#	0x8ca291	google.golang.org/grpc/internal/transport.NewHTTP2Client.func6+0xd1	google.golang.org/grpc@v1.78.0/internal/transport/http2_client.go:469

4038 @ 0x4833ae 0x4451b7 0x482585 0x5197c7 0x51aab9 0x51aaa7 0x5f7e85 0x608125 0xd0ca82 0x4b2037 0x49bcee 0x89bbe5 0x89bbb3 0x89c2ab 0x8e1545 0x8d4245 0x48bca1
#	0x482584	internal/poll.runtime_pollWait+0x84						runtime/netpoll.go:351
#	0x5197c6	internal/poll.(*pollDesc).wait+0x26						internal/poll/fd_poll_runtime.go:84
#	0x51aab8	internal/poll.(*pollDesc).waitRead+0x278					internal/poll/fd_poll_runtime.go:89
#	0x51aaa6	internal/poll.(*FD).Read+0x266							internal/poll/fd_unix.go:165
#	0x5f7e84	net.(*netFD).Read+0x24								net/fd_posix.go:68
#	0x608124	net.(*conn).Read+0x44								net/net.go:196
#	0xd0ca81	google.golang.org/grpc/credentials/alts/internal/conn.(*conn).Read+0x241	google.golang.org/grpc@v1.78.0/credentials/alts/internal/conn/record.go:182
#	0x4b2036	bufio.(*Reader).Read+0x196							bufio/bufio.go:245
#	0x49bced	io.ReadAtLeast+0x8d								io/io.go:335
#	0x89bbe4	io.ReadFull+0x64								io/io.go:354
#	0x89bbb2	golang.org/x/net/http2.readFrameHeader+0x32					golang.org/x/net@v0.49.0/http2/frame.go:242
#	0x89c2aa	golang.org/x/net/http2.(*Framer).ReadFrameHeader+0x6a				golang.org/x/net@v0.49.0/http2/frame.go:505
#	0x8e1544	google.golang.org/grpc/internal/transport.(*framer).readFrame+0x44		google.golang.org/grpc@v1.78.0/internal/transport/http_util.go:480
#	0x8d4244	google.golang.org/grpc/internal/transport.(*http2Client).reader+0x1c4		google.golang.org/grpc@v1.78.0/internal/transport/http2_client.go:1658

427 @ 0x4833ae 0x45f9b7 0x94ebcb 0x94c79a 0x48bca1
#	0x94ebca	google.golang.org/grpc.(*addrConn).resetTransportAndUnlock+0x6ea	google.golang.org/grpc@v1.78.0/clientconn.go:1377
#	0x94c799	google.golang.org/grpc.(*addrConn).connect+0x139			google.golang.org/grpc@v1.78.0/clientconn.go:997

56 @ 0x4833ae 0x45f9b7 0x148b825 0x48bca1
#	0x148b824	google.golang.org/grpc/balancer/weightedroundrobin.(*picker).start.func1+0xc4	google.golang.org/grpc@v1.78.0/balancer/weightedroundrobin/balancer.go:486

55 @ 0x4833ae 0x416af3 0x416672 0x841745 0x48bca1
#	0x841744	google.golang.org/grpc/internal/grpcsync.(*CallbackSerializer).run+0xe4	google.golang.org/grpc@v1.78.0/internal/grpcsync/callback_serializer.go:88

32 @ 0x4833ae 0x45f9b7 0x1479986 0x48bca1
#	0x1479985	google.golang.org/grpc/internal/xds/balancer/outlierdetection.(*outlierDetectionBalancer).run+0x105	google.golang.org/grpc@v1.78.0/internal/xds/balancer/outlierdetection/balancer.go:680

7 @ 0x4833ae 0x4451b7 0x482585 0x5197c7 0x51aab9 0x51aaa7 0x5f7e85 0x608125 0x66685b 0x4a3ed8 0x666a3e 0x663abb 0x66a3a5 0x66a3a6 0x4b2037 0x49bcee 0x89bbe5 0x89bbb3 0x89c2ab 0x8e1545 0x8d4245 0x48bca1
#	0x482584	internal/poll.runtime_pollWait+0x84					runtime/netpoll.go:351
#	0x5197c6	internal/poll.(*pollDesc).wait+0x26					internal/poll/fd_poll_runtime.go:84
#	0x51aab8	internal/poll.(*pollDesc).waitRead+0x278				internal/poll/fd_poll_runtime.go:89
#	0x51aaa6	internal/poll.(*FD).Read+0x266						internal/poll/fd_unix.go:165
#	0x5f7e84	net.(*netFD).Read+0x24							net/fd_posix.go:68
#	0x608124	net.(*conn).Read+0x44							net/net.go:196
#	0x66685a	crypto/tls.(*atLeastReader).Read+0x3a					crypto/tls/conn.go:819
#	0x4a3ed7	bytes.(*Buffer).ReadFrom+0x97						bytes/buffer.go:217
#	0x666a3d	crypto/tls.(*Conn).readFromUntil+0xdd					crypto/tls/conn.go:841
#	0x663aba	crypto/tls.(*Conn).readRecordOrCCS+0x3da				crypto/tls/conn.go:630
#	0x66a3a4	crypto/tls.(*Conn).readRecord+0x144					crypto/tls/conn.go:592
#	0x66a3a5	crypto/tls.(*Conn).Read+0x145						crypto/tls/conn.go:1397
#	0x4b2036	bufio.(*Reader).Read+0x196						bufio/bufio.go:245
#	0x49bced	io.ReadAtLeast+0x8d							io/io.go:335
#	0x89bbe4	io.ReadFull+0x64							io/io.go:354
#	0x89bbb2	golang.org/x/net/http2.readFrameHeader+0x32				golang.org/x/net@v0.49.0/http2/frame.go:242
#	0x89c2aa	golang.org/x/net/http2.(*Framer).ReadFrameHeader+0x6a			golang.org/x/net@v0.49.0/http2/frame.go:505
#	0x8e1544	google.golang.org/grpc/internal/transport.(*framer).readFrame+0x44	google.golang.org/grpc@v1.78.0/internal/transport/http_util.go:480
#	0x8d4244	google.golang.org/grpc/internal/transport.(*http2Client).reader+0x1c4	google.golang.org/grpc@v1.78.0/internal/transport/http2_client.go:1658

6 @ 0x4833ae 0x416af3 0x416672 0x11b4c85 0x48bca1
#	0x11b4c84	google.golang.org/grpc/internal/xds/clients/internal/syncutil.(*CallbackSerializer).run+0xe4	google.golang.org/grpc@v1.78.0/internal/xds/clients/internal/syncutil/callback_serializer.go:88

6 @ 0x4833ae 0x45f9b7 0x8d4a66 0x48bca1
#	0x8d4a65	google.golang.org/grpc/internal/transport.(*http2Client).keepalive+0x185	google.golang.org/grpc@v1.78.0/internal/transport/http2_client.go:1732

5 @ 0x4833ae 0x4451b7 0x482585 0x5197c7 0x51aab9 0x51aaa7 0x5f7e85 0x608125 0x739c87 0x4b1b03 0x4b1c33 0x73a792 0x48bca1
#	0x482584	internal/poll.runtime_pollWait+0x84		runtime/netpoll.go:351
#	0x5197c6	internal/poll.(*pollDesc).wait+0x26		internal/poll/fd_poll_runtime.go:84
#	0x51aab8	internal/poll.(*pollDesc).waitRead+0x278	internal/poll/fd_poll_runtime.go:89
#	0x51aaa6	internal/poll.(*FD).Read+0x266			internal/poll/fd_unix.go:165
#	0x5f7e84	net.(*netFD).Read+0x24				net/fd_posix.go:68
#	0x608124	net.(*conn).Read+0x44				net/net.go:196
#	0x739c86	net/http.(*persistConn).Read+0x46		net/http/transport.go:2125
#	0x4b1b02	bufio.(*Reader).fill+0x102			bufio/bufio.go:113
#	0x4b1c32	bufio.(*Reader).Peek+0x52			bufio/bufio.go:152
#	0x73a791	net/http.(*persistConn).readLoop+0x171		net/http/transport.go:2278

5 @ 0x4833ae 0x45f9b7 0x73c1a7 0x48bca1
#	0x73c1a6	net/http.(*persistConn).writeLoop+0xe6	net/http/transport.go:2600

4 @ 0x4833ae 0x45f9b7 0x14805e9 0x48bca1
#	0x14805e8	google.golang.org/grpc/internal/xds/balancer/priority.(*priorityBalancer).run+0x88	google.golang.org/grpc@v1.78.0/internal/xds/balancer/priority/balancer.go:267

4 @ 0x4833ae 0x45f9b7 0x14976da 0x48bca1
#	0x14976d9	google.golang.org/grpc/internal/xds/balancer/clusterresolver.(*clusterResolverBalancer).run+0xb9	google.golang.org/grpc@v1.78.0/internal/xds/balancer/clusterresolver/clusterresolver.go:319

4 @ 0x4833ae 0x45f9b7 0x8edd0b 0x48bca1
#	0x8edd0a	google.golang.org/grpc/internal/resolver/dns.(*dnsResolver).watcher+0x24a	google.golang.org/grpc@v1.78.0/internal/resolver/dns/dns_resolver.go:221

4 @ 0x4833ae 0x45f9b7 0x9668ec 0x48bca1
#	0x9668eb	google.golang.org/grpc.newClientStreamWithParams.func4+0x8b	google.golang.org/grpc@v1.78.0/stream.go:425

2 @ 0x4833ae 0x45f9b7 0x119d3bd 0x119d1d2 0x8ece57 0x119ce7f 0x48bca1
#	0x119d3bc	google.golang.org/grpc/internal/xds/clients/lrsclient.(*streamImpl).sendLoads+0x11c	google.golang.org/grpc@v1.78.0/internal/xds/clients/lrsclient/lrs_stream.go:153
#	0x119d1d1	google.golang.org/grpc/internal/xds/clients/lrsclient.(*streamImpl).runner.func1+0x2d1	google.golang.org/grpc@v1.78.0/internal/xds/clients/lrsclient/lrs_stream.go:140
#	0x8ece56	google.golang.org/grpc/internal/backoff.RunF+0xd6					google.golang.org/grpc@v1.78.0/internal/backoff/backoff.go:97
#	0x119ce7e	google.golang.org/grpc/internal/xds/clients/lrsclient.(*streamImpl).runner+0x17e	google.golang.org/grpc@v1.78.0/internal/xds/clients/lrsclient/lrs_stream.go:143

2 @ 0x4833ae 0x45f9b7 0x140b050 0x48bca1
#	0x140b04f	google.golang.org/grpc/internal/xds/clients/xdsclient.(*adsStreamImpl).send+0xcf	google.golang.org/grpc@v1.78.0/internal/xds/clients/xdsclient/ads_stream.go:281

2 @ 0x4833ae 0x45f9b7 0x8e4707 0x8e4165 0x8e52e5 0x8e4ec9 0x9561fb 0x9571d7 0x957e2b 0x96acd7 0x969e7f 0x9689af 0x969c75 0x141cb06 0x140c5fb 0x140bf98 0x140ae79 0x119add7 0x140ac71 0x48bca1
#	0x8e4706	google.golang.org/grpc/internal/transport.(*recvBufferReader).readMessageHeaderClient+0xa6	google.golang.org/grpc@v1.78.0/internal/transport/transport.go:198
#	0x8e4164	google.golang.org/grpc/internal/transport.(*recvBufferReader).ReadMessageHeader+0x44		google.golang.org/grpc@v1.78.0/internal/transport/transport.go:144
#	0x8e52e4	google.golang.org/grpc/internal/transport.(*transportReader).ReadMessageHeader+0x24		google.golang.org/grpc@v1.78.0/internal/transport/transport.go:441
#	0x8e4ec8	google.golang.org/grpc/internal/transport.(*Stream).ReadMessageHeader+0xa8			google.golang.org/grpc@v1.78.0/internal/transport/transport.go:366
#	0x9561fa	google.golang.org/grpc.(*parser).recvMsg+0x3a							google.golang.org/grpc@v1.78.0/rpc_util.go:772
#	0x9571d6	google.golang.org/grpc.recvAndDecompress+0x96							google.golang.org/grpc@v1.78.0/rpc_util.go:931
#	0x957e2a	google.golang.org/grpc.recv+0xaa								google.golang.org/grpc@v1.78.0/rpc_util.go:1014
#	0x96acd6	google.golang.org/grpc.(*csAttempt).recvMsg+0x356						google.golang.org/grpc@v1.78.0/stream.go:1164
#	0x969e7e	google.golang.org/grpc.(*clientStream).RecvMsg.func1+0x1e					google.golang.org/grpc@v1.78.0/stream.go:1011
#	0x9689ae	google.golang.org/grpc.(*clientStream).withRetry+0x3ce						google.golang.org/grpc@v1.78.0/stream.go:815
#	0x969c74	google.golang.org/grpc.(*clientStream).RecvMsg+0x154						google.golang.org/grpc@v1.78.0/stream.go:1010
#	0x141cb05	google.golang.org/grpc/internal/xds/clients/grpctransport.(*stream).Recv+0x45			google.golang.org/grpc@v1.78.0/internal/xds/clients/grpctransport/grpc_transport.go:208
#	0x140c5fa	google.golang.org/grpc/internal/xds/clients/xdsclient.(*adsStreamImpl).recvMessage+0x3a		google.golang.org/grpc@v1.78.0/internal/xds/clients/xdsclient/ads_stream.go:476
#	0x140bf97	google.golang.org/grpc/internal/xds/clients/xdsclient.(*adsStreamImpl).recv+0x77		google.golang.org/grpc@v1.78.0/internal/xds/clients/xdsclient/ads_stream.go:438
#	0x140ae78	google.golang.org/grpc/internal/xds/clients/xdsclient.(*adsStreamImpl).runner.func1+0x1b8	google.golang.org/grpc@v1.78.0/internal/xds/clients/xdsclient/ads_stream.go:265
#	0x119add6	google.golang.org/grpc/internal/xds/clients/internal/backoff.RunF+0xd6				google.golang.org/grpc@v1.78.0/internal/xds/clients/internal/backoff/backoff.go:112
#	0x140ac70	google.golang.org/grpc/internal/xds/clients/xdsclient.(*adsStreamImpl).runner+0xf0		google.golang.org/grpc@v1.78.0/internal/xds/clients/xdsclient/ads_stream.go:270

1 @ 0x411017 0x82f951 0x8c7505 0x8c74a6 0x8c7ac5 0x94f905 0x94f5c8 0x94e6a5 0x94c79a 0x48bca1
#	0x82f950	google.golang.org/grpc/attributes.(*Attributes).Value+0x30		google.golang.org/grpc@v1.78.0/attributes/attributes.go:70
#	0x8c7504	google.golang.org/grpc/internal/transport/networktype.Get+0xc4		google.golang.org/grpc@v1.78.0/internal/transport/networktype/networktype.go:41
#	0x8c74a5	google.golang.org/grpc/internal/transport.dial+0x65			google.golang.org/grpc@v1.78.0/internal/transport/http2_client.go:160
#	0x8c7ac4	google.golang.org/grpc/internal/transport.NewHTTP2Client+0x164		google.golang.org/grpc@v1.78.0/internal/transport/http2_client.go:222
#	0x94f904	google.golang.org/grpc.(*addrConn).createTransport+0x284		google.golang.org/grpc@v1.78.0/clientconn.go:1519
#	0x94f5c7	google.golang.org/grpc.(*addrConn).tryAllAddrs+0x467			google.golang.org/grpc@v1.78.0/clientconn.go:1466
#	0x94e6a4	google.golang.org/grpc.(*addrConn).resetTransportAndUnlock+0x1c4	google.golang.org/grpc@v1.78.0/clientconn.go:1349
#	0x94c799	google.golang.org/grpc.(*addrConn).connect+0x139			google.golang.org/grpc@v1.78.0/clientconn.go:997

1 @ 0x41c4a9 0x4859e9 0xab7333 0x48bca1
#	0x4859e8	os/signal.signal_recv+0x28	runtime/sigqueue.go:152
#	0xab7332	os/signal.loop+0x12		os/signal/signal_unix.go:23

1 @ 0x4833ae 0x416af3 0x416652 0x17a8765 0x48bca1
#	0x17a8764	cloud.google.com/go/pubsub.(*Subscription).Receive.func3+0x44	cloud.google.com/go/pubsub@v1.50.1/subscription.go:1519

1 @ 0x4833ae 0x416af3 0x416672 0x10708d2 0x48bca1
#	0x10708d1	google.golang.org/grpc/balancer/rls.(*controlChannel).monitorConnectivityState+0x231	google.golang.org/grpc@v1.78.0/balancer/rls/control_channel.go:191

1 @ 0x4833ae 0x416af3 0x416672 0x1871298 0x48bca1
#	0x1871297	gitlab.com/levenlabs/backend/dank/seaweed.(*Seaweed).refreshSpin+0x57	gitlab.com/levenlabs/backend/dank/seaweed/seaweed.go:307

1 @ 0x4833ae 0x4451b7 0x482585 0x5197c7 0x51aab9 0x51aaa7 0x5f7e85 0x608125 0x4b1f82 0x49cbb3 0x16c6aed 0x718eb4 0x4b1b03 0x4b1c33 0x71e6e5 0x48bca1
#	0x482584	internal/poll.runtime_pollWait+0x84			runtime/netpoll.go:351
#	0x5197c6	internal/poll.(*pollDesc).wait+0x26			internal/poll/fd_poll_runtime.go:84
#	0x51aab8	internal/poll.(*pollDesc).waitRead+0x278		internal/poll/fd_poll_runtime.go:89
#	0x51aaa6	internal/poll.(*FD).Read+0x266				internal/poll/fd_unix.go:165
#	0x5f7e84	net.(*netFD).Read+0x24					net/fd_posix.go:68
#	0x608124	net.(*conn).Read+0x44					net/net.go:196
#	0x4b1f81	bufio.(*Reader).Read+0xe1				bufio/bufio.go:231
#	0x49cbb2	io.(*multiReader).Read+0x92				io/multi.go:26
#	0x16c6aec	github.com/pires/go-proxyproto.(*Conn).Read+0x8c	github.com/pires/go-proxyproto@v0.9.2/protocol.go:184
#	0x718eb3	net/http.(*connReader).Read+0x153			net/http/server.go:812
#	0x4b1b02	bufio.(*Reader).fill+0x102				bufio/bufio.go:113
#	0x4b1c32	bufio.(*Reader).Peek+0x52				bufio/bufio.go:152
#	0x71e6e4	net/http.(*conn).serve+0x7c4				net/http/server.go:2145

1 @ 0x4833ae 0x4451b7 0x482585 0x5197c7 0x51aab9 0x51aaa7 0x5f7e85 0x608125 0x4b2037 0x49bcee 0x89bbe5 0x89bbb3 0x89c2ab 0x8e1545 0x8d4245 0x48bca1
#	0x482584	internal/poll.runtime_pollWait+0x84					runtime/netpoll.go:351
#	0x5197c6	internal/poll.(*pollDesc).wait+0x26					internal/poll/fd_poll_runtime.go:84
#	0x51aab8	internal/poll.(*pollDesc).waitRead+0x278				internal/poll/fd_poll_runtime.go:89
#	0x51aaa6	internal/poll.(*FD).Read+0x266						internal/poll/fd_unix.go:165
#	0x5f7e84	net.(*netFD).Read+0x24							net/fd_posix.go:68
#	0x608124	net.(*conn).Read+0x44							net/net.go:196
#	0x4b2036	bufio.(*Reader).Read+0x196						bufio/bufio.go:245
#	0x49bced	io.ReadAtLeast+0x8d							io/io.go:335
#	0x89bbe4	io.ReadFull+0x64							io/io.go:354
#	0x89bbb2	golang.org/x/net/http2.readFrameHeader+0x32				golang.org/x/net@v0.49.0/http2/frame.go:242
#	0x89c2aa	golang.org/x/net/http2.(*Framer).ReadFrameHeader+0x6a			golang.org/x/net@v0.49.0/http2/frame.go:505
#	0x8e1544	google.golang.org/grpc/internal/transport.(*framer).readFrame+0x44	google.golang.org/grpc@v1.78.0/internal/transport/http_util.go:480
#	0x8d4244	google.golang.org/grpc/internal/transport.(*http2Client).reader+0x1c4	google.golang.org/grpc@v1.78.0/internal/transport/http2_client.go:1658

1 @ 0x4833ae 0x4451b7 0x482585 0x5197c7 0x51ebec 0x51ebda 0x5f9d29 0x610efb 0x60ffb0 0x16cfbaf 0x16d04ac 0x16c6339 0x16cd955 0x723e6c 0x17ff4ef 0x48bca1
#	0x482584	internal/poll.runtime_pollWait+0x84								runtime/netpoll.go:351
#	0x5197c6	internal/poll.(*pollDesc).wait+0x26								internal/poll/fd_poll_runtime.go:84
#	0x51ebeb	internal/poll.(*pollDesc).waitRead+0x28b							internal/poll/fd_poll_runtime.go:89
#	0x51ebd9	internal/poll.(*FD).Accept+0x279								internal/poll/fd_unix.go:613
#	0x5f9d28	net.(*netFD).accept+0x28									net/fd_unix.go:161
#	0x610efa	net.(*TCPListener).accept+0x1a									net/tcpsock_posix.go:159
#	0x60ffaf	net.(*TCPListener).AcceptTCP+0x2f								net/tcpsock.go:367
#	0x16cfbae	gitlab.com/levenlabs/backend/go-llib/lnet.ConfiguredTCPListener.func1.TCPKeepAlive.2.1+0x2e	gitlab.com/levenlabs/backend/go-llib@v0.3.10/lnet/lnet.go:68
#	0x16d04ab	gitlab.com/levenlabs/backend/go-llib/lnet.acceptWrap.Accept+0x2b				gitlab.com/levenlabs/backend/go-llib@v0.3.10/lnet/lnet.go:35
#	0x16c6338	github.com/pires/go-proxyproto.(*Listener).Accept+0x38						github.com/pires/go-proxyproto@v0.9.2/protocol.go:88
#	0x16cd954	gitlab.com/levenlabs/backend/go-llib/lnet.(*Swapper).Accept+0x34				gitlab.com/levenlabs/backend/go-llib@v0.3.10/lnet/lnet.go:171
#	0x723e6b	net/http.(*Server).Serve+0x30b									net/http/server.go:3463
#	0x17ff4ee	gitlab.com/levenlabs/backend/go-llib/lhttp.ConfiguredServer.func2.1+0x2e			gitlab.com/levenlabs/backend/go-llib@v0.3.10/lhttp/server.go:318

1 @ 0x4833ae 0x45f9b7 0x10690f2 0x48bca1
#	0x10690f1	google.golang.org/grpc/balancer/rls.(*rlsBalancer).run+0x171	google.golang.org/grpc@v1.78.0/balancer/rls/balancer.go:232

1 @ 0x4833ae 0x45f9b7 0x1069646 0x48bca1
#	0x1069645	google.golang.org/grpc/balancer/rls.(*rlsBalancer).purgeDataCache+0xa5	google.golang.org/grpc@v1.78.0/balancer/rls/balancer.go:273

1 @ 0x4833ae 0x45f9b7 0x150db25 0x150d98f 0x48bca1
#	0x150db24	go.opentelemetry.io/otel/sdk/metric.(*PeriodicReader).run+0x124		go.opentelemetry.io/otel/sdk/metric@v1.39.0/periodic_reader.go:187
#	0x150d98e	go.opentelemetry.io/otel/sdk/metric.NewPeriodicReader.func2+0x4e	go.opentelemetry.io/otel/sdk/metric@v1.39.0/periodic_reader.go:128

1 @ 0x4833ae 0x45f9b7 0x17988ac 0x48bca1
#	0x17988ab	cloud.google.com/go/pubsub.(*messageIterator).sender+0x24b	cloud.google.com/go/pubsub@v1.50.1/iterator.go:475

1 @ 0x4833ae 0x45f9b7 0x18001c5 0x48bca1
#	0x18001c4	gitlab.com/levenlabs/backend/go-llib/lhttp.(*Waiter).spin+0x84	gitlab.com/levenlabs/backend/go-llib@v0.3.10/lhttp/waiter.go:46

1 @ 0x4833ae 0x45f9b7 0x1849c53 0x48bca1
#	0x1849c52	gitlab.com/levenlabs/backend/go-llib/ldb.(*PubSubConsumer).Consume.func1+0x132	gitlab.com/levenlabs/backend/go-llib@v0.3.10/ldb/pubsub.go:2193

1 @ 0x4833ae 0x45f9b7 0x8bf1a5 0x96aa97 0x96aa87 0x969e7f 0x968722 0x969c75 0x947864 0x94771f 0xd6dfbd 0xd7d393 0x1774b48 0x1790206 0x178ae77 0xc65c17 0xc6597b 0x178ad25 0x179839e 0x17982ce 0x1796d98 0x17a89cb 0x1761bb0 0x48bca1
#	0x8bf1a4	google.golang.org/grpc/internal/transport.(*ClientStream).waitOnHeader+0x64	google.golang.org/grpc@v1.78.0/internal/transport/client_stream.go:94
#	0x96aa96	google.golang.org/grpc/internal/transport.(*ClientStream).RecvCompress+0x116	google.golang.org/grpc@v1.78.0/internal/transport/client_stream.go:109
#	0x96aa86	google.golang.org/grpc.(*csAttempt).recvMsg+0x106				google.golang.org/grpc@v1.78.0/stream.go:1146
#	0x969e7e	google.golang.org/grpc.(*clientStream).RecvMsg.func1+0x1e			google.golang.org/grpc@v1.78.0/stream.go:1011
#	0x968721	google.golang.org/grpc.(*clientStream).withRetry+0x141				google.golang.org/grpc@v1.78.0/stream.go:831
#	0x969c74	google.golang.org/grpc.(*clientStream).RecvMsg+0x154				google.golang.org/grpc@v1.78.0/stream.go:1010
#	0x947863	google.golang.org/grpc.invoke+0xc3						google.golang.org/grpc@v1.78.0/call.go:73
#	0x94771e	google.golang.org/grpc.(*ClientConn).Invoke+0x23e				google.golang.org/grpc@v1.78.0/call.go:37
#	0xd6dfbc	cloud.google.com/go/auth/grpctransport.(*roundRobinConnPool).Invoke+0x9c	cloud.google.com/go/auth@v0.18.1/grpctransport/pool.go:88
#	0xd7d392	google.golang.org/api/transport/grpc.(*poolAdapter).Invoke+0x72			google.golang.org/api@v0.264.0/transport/grpc/pool.go:112
#	0x1774b47	cloud.google.com/go/pubsub/v2/apiv1/pubsubpb.(*subscriberClient).Pull+0xc7	cloud.google.com/go/pubsub/v2@v2.0.0/apiv1/pubsubpb/pubsub.pb.go:9379
#	0x1790205	cloud.google.com/go/pubsub/apiv1.executeRPC[...]+0x225				cloud.google.com/go/pubsub@v1.50.1/apiv1/helpers.go:96
#	0x178ae76	cloud.google.com/go/pubsub/apiv1.(*subscriberGRPCClient).Pull.func1+0xd6	cloud.google.com/go/pubsub@v1.50.1/apiv1/subscriber_client.go:1065
#	0xc65c16	github.com/googleapis/gax-go/v2.invoke+0x136					github.com/googleapis/gax-go/v2@v2.16.0/invoke.go:82
#	0xc6597a	github.com/googleapis/gax-go/v2.Invoke+0xda					github.com/googleapis/gax-go/v2@v2.16.0/invoke.go:50
#	0x178ad24	cloud.google.com/go/pubsub/apiv1.(*subscriberGRPCClient).Pull+0x2c4		cloud.google.com/go/pubsub@v1.50.1/apiv1/subscriber_client.go:1063
#	0x179839d	cloud.google.com/go/pubsub/apiv1.(*SubscriberClient).Pull+0x17d			cloud.google.com/go/pubsub@v1.50.1/apiv1/subscriber_client.go:631
#	0x17982cd	cloud.google.com/go/pubsub.(*messageIterator).pullMessages+0xad			cloud.google.com/go/pubsub@v1.50.1/iterator.go:404
#	0x1796d97	cloud.google.com/go/pubsub.(*messageIterator).receive+0x137			cloud.google.com/go/pubsub@v1.50.1/iterator.go:274
#	0x17a89ca	cloud.google.com/go/pubsub.(*Subscription).Receive.func2+0x1ca			cloud.google.com/go/pubsub@v1.50.1/subscription.go:1401
#	0x1761baf	golang.org/x/sync/errgroup.(*Group).Go.func1+0x4f				golang.org/x/sync@v0.19.0/errgroup/errgroup.go:93

1 @ 0x4833ae 0x460add 0x460ab4 0x484eee 0x497a65 0x1761a5e 0x17a8665 0x1846645 0x18497ea 0x48bca1
#	0x484eed	sync.runtime_SemacquireWaitGroup+0x2d							runtime/sema.go:114
#	0x497a64	sync.(*WaitGroup).Wait+0x84								sync/waitgroup.go:206
#	0x1761a5d	golang.org/x/sync/errgroup.(*Group).Wait+0x1d						golang.org/x/sync@v0.19.0/errgroup/errgroup.go:56
#	0x17a8664	cloud.google.com/go/pubsub.(*Subscription).Receive+0x904				cloud.google.com/go/pubsub@v1.50.1/subscription.go:1533
#	0x1846644	gitlab.com/levenlabs/backend/go-llib/ldb.(*PubSubTopicConsumer).Consume+0x2924		gitlab.com/levenlabs/backend/go-llib@v0.3.10/ldb/pubsub.go:1712
#	0x18497e9	gitlab.com/levenlabs/backend/go-llib/ldb.(*PubSubConsumer).refreshTopics.func1+0x449	gitlab.com/levenlabs/backend/go-llib@v0.3.10/ldb/pubsub.go:2150

1 @ 0x4833ae 0x460add 0x460ab4 0x484eee 0x497a65 0x1849ab0 0x1871b8d 0x1871b8e 0x48bca1
#	0x484eed	sync.runtime_SemacquireWaitGroup+0x2d						runtime/sema.go:114
#	0x497a64	sync.(*WaitGroup).Wait+0x84							sync/waitgroup.go:206
#	0x1849aaf	gitlab.com/levenlabs/backend/go-llib/ldb.(*PubSubConsumer).Consume+0x22f	gitlab.com/levenlabs/backend/go-llib@v0.3.10/ldb/pubsub.go:2206
#	0x1871b8c	gitlab.com/levenlabs/backend/go-cron.(*Consumer).Consume+0x2c			gitlab.com/levenlabs/backend/go-cron@v0.1.2/cron.go:325
#	0x1871b8d	main.main.func2+0x2d								gitlab.com/levenlabs/backend/dank/cmd/seaweed-backuper/backuper.go:44

We do see a matching increase in the storage.googleapis.com/client/grpc/lb/wrr/rr_fallback metric (which by the way isn't documented) in the Stackdriver metrics:

Similarly we see a spike in the storage.googleapis.com/client/grpc/lb/wrr/endpoint_weight_not_yet_usable metric (also not documented):

[jameshartig]

Updated the above since we realized the service uses gRPC for GCS as well as Pub/Sub. We haven't identified which yet but we recently deployed a change that starts ingesting the new subchannel metrics via the experimental/stats package. This will hopefully help us narrow down the target as well as maybe some other details about the connections.

[jameshartig]

Looks like this is definitely caused by something with GCS+DirectConnectivity.

During the most recent FD spike there was a large spike in grpc.subchannel.open.connections for the target google-c2p:///storage.googleapis.com:

This seems to narrow it down to something related to direct connectivity.

I'm seeing a lot of connection attempts that succeeded (grpc.subchannel.connection_attempts_succeeded) but not a lot that failed (grpc.subchannel.connection_attempts_failed) (until we started to run out of open FDs):

vs

I'm also seeing similar spikes for grpc.subchannel.disconnections

So is the load balancer closing them? Unfortunately we didn't track the optional label disconnect_error (but it looks like that's only ever sent "unknown"?).

A large increase in grpc.lb.wrr.rr_fallback:

Not a huge amount of grpc.xds_client.resource_updates_valid but it did go up from 0: