infinite ResolveNow() loop on net transients

[lev-lb]

What version of gRPC are you using?

client: v1.70.0, server: v1.61.1, v1.63.2, v1.66.0.

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

go version go1.22.11 linux/amd64

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

several Linux versions, including: kernel 4.15.0-112-generic on Ubuntu

What did you do?

gRPC client with a custom resolver (using pick_first LB), connecting to a multi-node server cluster. this codebase appeared to be working fine for about 6 years, up to and including gRPC v1.63.2 - or at least the issue below was never brought to our attention before. since upgrading to v1.70.0, the same code appears to occasionally enter infinite loop calling the custom resolver's ResolveNow() method. the issue is non-deterministic, but has been observed 4-5 times in the past month, AFAICT - always on network transients (impaired connectivity to the gRPC servers cluster).

What did you expect to see?

the problem appears some time after the initial conn was established, lost, re-established, etc. after a net hiccup, i'd expect the lower gRPC layers to keep trying to dial the addresses returned by ResolveNow() as per the backoff and connect timeout config - which it normally does, and has been doing for years. an example of this is at the top of the attached log.

What did you see instead?

occasionally (but rarely, despite forcibly injecting various network faults), the gRPC code enters an infinite loop of calling ResolveNow() at a rate of >15 thousand calls/second, pegging several CPU cores (>210% CPU on an otherwise near-idle machine). the process does not recover. the issue appears to manifest somewhere around here:

2025-03-07T12:48:28.072	INFO	[core] [Channel #1 SubChannel #2]Subchannel Connectivity change to IDLE
2025-03-07T12:48:28.072	INFO	resolver.ResolveNow()	{"lbgrpc": "1i855hu", "targets": "192.168.19.217:443,192.168.19.218:443,192.168.19.220:443,192.168.25.23:443,192.168.26.25:443,192.168.29.142:443,192.168.29.144:443,192.168.16.233:443,192.168.17.106:443,192.168.17.107:443,192.168.17.30:443,192.168.19.213:443,192.168.19.214:443,192.168.19.215:443", "calls-last-sec": 0}
2025-03-07T12:48:28.072	INFO	[transport] [client-transport 0xc000bc46c8] loopyWriter exiting with error: received GOAWAY with no active streams
2025-03-07T12:48:28.072	INFO	[pick-first-lb] [pick-first-lb 0xc000a37d70] Received SubConn state update: 0xc0002bb5e0, {ConnectivityState:IDLE ConnectionError:<nil> connectedAddress:{Addr: ServerName: Attributes:<nil> BalancerAttributes:<nil> Metadata:<nil>}}
2025-03-07T12:48:28.073	INFO	[core] blockingPicker: the picked transport is not ready, loop back to repick
2025-03-07T12:48:28.073	INFO	[core] [Channel #1]Resolver state updated: { "Addresses": [ { "Addr": "192.168.19.217:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.19.218:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.19.220:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.25.23:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.26.25:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.29.142:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.29.144:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.16.233:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.17.106:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.17.107:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.17.30:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.19.213:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.19.214:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.19.215:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null } ], "Endpoints": null, "ServiceConfig": null, "Attributes": null} ()
2025-03-07T12:48:28.073	INFO	[core] [Channel #1]Channel Connectivity change to IDLE
2025-03-07T12:48:28.073	INFO	[transport] [client-transport 0xc000bc46c8] Closing: connection error: desc = "error reading from server: read tcp 10.212.1.6:32844->192.168.19.215:443: use of closed network connection"
2025-03-07T12:48:28.073	INFO	[pick-first-lb] [pick-first-lb 0xc000a37d70] Received new config { "shuffleAddressList": false}, resolver state { "Addresses": [ { "Addr": "192.168.19.217:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.19.218:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.19.220:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.25.23:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.26.25:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.29.142:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.29.144:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.16.233:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.17.106:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.17.107:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.17.30:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.19.213:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.19.214:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.19.215:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null } ], "Endpoints": null, "ServiceConfig": null, "Attributes": null}
2025-03-07T12:48:28.073	INFO	[core] [Channel #1 SubChannel #2]addrConn: updateAddrs addrs (5 of 14): [{Addr: "192.168.19.217:443", ServerName: "", } {Addr: "192.168.19.218:443", ServerName: "", } {Addr: "192.168.19.220:443", ServerName: "", } {Addr: "192.168.25.23:443", ServerName: "", } {Addr: "192.168.26.25:443", ServerName: "", }]
2025-03-07T12:48:28.073	INFO	[core] [Channel #1 SubChannel #2]Subchannel Connectivity change to CONNECTING
2025-03-07T12:48:28.073	INFO	[core] [Channel #1 SubChannel #2]Subchannel picks a new address "192.168.19.215:443" to connect
2025-03-07T12:48:28.073	INFO	[pick-first-lb] [pick-first-lb 0xc000a37d70] Received SubConn state update: 0xc0002bb5e0, {ConnectivityState:CONNECTING ConnectionError:<nil> connectedAddress:{Addr: ServerName: Attributes:<nil> BalancerAttributes:<nil> Metadata:<nil>}}
2025-03-07T12:48:28.073	INFO	[core] [Channel #1]Channel Connectivity change to CONNECTING
2025-03-07T12:48:28.073	INFO	[core] [Channel #1 SubChannel #2]Subchannel picks a new address "192.168.19.217:443" to connect
2025-03-07T12:48:28.073	INFO	[core] Creating new client transport to "{Addr: \"192.168.19.215:443\", ServerName: \"lb-resolver\", }": connection error: desc = "transport: Error while dialing: dial tcp 192.168.19.215:443: operation was canceled"
2025-03-07T12:48:28.073	WARN	[core] [Channel #1 SubChannel #2]grpc: addrConn.createTransport failed to connect to {Addr: "192.168.19.215:443", ServerName: "lb-resolver", }. Err: connection error: desc = "transport: Error while dialing: dial tcp 192.168.19.215:443: operation was canceled"
2025-03-07T12:48:28.073	INFO	resolver.ResolveNow()	{"lbgrpc": "1i855hu", "targets": "192.168.19.218:443,192.168.19.220:443,192.168.25.23:443,192.168.26.25:443,192.168.29.142:443,192.168.29.144:443,192.168.16.233:443,192.168.17.106:443,192.168.17.107:443,192.168.17.30:443,192.168.19.213:443,192.168.19.214:443,192.168.19.215:443,192.168.19.217:443", "calls-last-sec": 1}
2025-03-07T12:48:28.074	INFO	[core] [Channel #1]Resolver state updated: { "Addresses": [ { "Addr": "192.168.19.218:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.19.220:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.25.23:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.26.25:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.29.142:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.29.144:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.16.233:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.17.106:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.17.107:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.17.30:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.19.213:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.19.214:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.19.215:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.19.217:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null } ], "Endpoints": null, "ServiceConfig": null, "Attributes": null} ()
2025-03-07T12:48:28.074	INFO	[pick-first-lb] [pick-first-lb 0xc000a37d70] Received new config { "shuffleAddressList": false}, resolver state { "Addresses": [ { "Addr": "192.168.19.218:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.19.220:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.25.23:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.26.25:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.29.142:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.29.144:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.16.233:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.17.106:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.17.107:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.17.30:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.19.213:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.19.214:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.19.215:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.19.217:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null } ], "Endpoints": null, "ServiceConfig": null, "Attributes": null}
2025-03-07T12:48:28.074	INFO	[core] [Channel #1 SubChannel #2]addrConn: updateAddrs addrs (5 of 14): [{Addr: "192.168.19.218:443", ServerName: "", } {Addr: "192.168.19.220:443", ServerName: "", } {Addr: "192.168.25.23:443", ServerName: "", } {Addr: "192.168.26.25:443", ServerName: "", } {Addr: "192.168.29.142:443", ServerName: "", }]
2025-03-07T12:48:28.074	INFO	[core] Creating new client transport to "{Addr: \"192.168.19.217:443\", ServerName: \"lb-resolver\", }": connection error: desc = "transport: Error while dialing: dial tcp 192.168.19.217:443: operation was canceled"
2025-03-07T12:48:28.074	WARN	[core] [Channel #1 SubChannel #2]grpc: addrConn.createTransport failed to connect to {Addr: "192.168.19.217:443", ServerName: "lb-resolver", }. Err: connection error: desc = "transport: Error while dialing: dial tcp 192.168.19.217:443: operation was canceled"
2025-03-07T12:48:28.074	INFO	resolver.ResolveNow()	{"lbgrpc": "1i855hu", "targets": "192.168.19.220:443,192.168.25.23:443,192.168.26.25:443,192.168.29.142:443,192.168.29.144:443,192.168.16.233:443,192.168.17.106:443,192.168.17.107:443,192.168.17.30:443,192.168.19.213:443,192.168.19.214:443,192.168.19.215:443,192.168.19.217:443,192.168.19.218:443", "calls-last-sec": 2}
2025-03-07T12:48:28.074	INFO	[core] [Channel #1 SubChannel #2]Subchannel picks a new address "192.168.19.218:443" to connect
2025-03-07T12:48:28.074	INFO	[core] [Channel #1]Resolver state updated: { "Addresses": [ { "Addr": "192.168.19.220:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.25.23:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.26.25:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.29.142:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.29.144:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.16.233:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.17.106:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.17.107:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.17.30:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.19.213:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.19.214:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.19.215:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.19.217:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.19.218:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null } ], "Endpoints": null, "ServiceConfig": null, "Attributes": null} ()
2025-03-07T12:48:28.074	INFO	[pick-first-lb] [pick-first-lb 0xc000a37d70] Received new config { "shuffleAddressList": false}, resolver state { "Addresses": [ { "Addr": "192.168.19.220:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.25.23:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.26.25:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.29.142:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.29.144:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.16.233:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.17.106:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.17.107:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.17.30:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.19.213:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.19.214:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.19.215:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.19.217:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.19.218:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null } ], "Endpoints": null, "ServiceConfig": null, "Attributes": null}
2025-03-07T12:48:28.074	INFO	[core] [Channel #1 SubChannel #2]addrConn: updateAddrs addrs (5 of 14): [{Addr: "192.168.19.220:443", ServerName: "", } {Addr: "192.168.25.23:443", ServerName: "", } {Addr: "192.168.26.25:443", ServerName: "", } {Addr: "192.168.29.142:443", ServerName: "", } {Addr: "192.168.29.144:443", ServerName: "", }]
2025-03-07T12:48:28.075	INFO	[core] Creating new client transport to "{Addr: \"192.168.19.218:443\", ServerName: \"lb-resolver\", }": connection error: desc = "transport: Error while dialing: dial tcp 192.168.19.218:443: operation was canceled"
2025-03-07T12:48:28.075	WARN	[core] [Channel #1 SubChannel #2]grpc: addrConn.createTransport failed to connect to {Addr: "192.168.19.218:443", ServerName: "lb-resolver", }. Err: connection error: desc = "transport: Error while dialing: dial tcp 192.168.19.218:443: operation was canceled"
2025-03-07T12:48:28.075	INFO	resolver.ResolveNow()	{"lbgrpc": "1i855hu", "targets": "192.168.25.23:443,192.168.26.25:443,192.168.29.142:443,192.168.29.144:443,192.168.16.233:443,192.168.17.106:443,192.168.17.107:443,192.168.17.30:443,192.168.19.213:443,192.168.19.214:443,192.168.19.215:443,192.168.19.217:443,192.168.19.218:443,192.168.19.220:443", "calls-last-sec": 3}
2025-03-07T12:48:28.075	INFO	[core] [Channel #1]Resolver state updated: { "Addresses": [ { "Addr": "192.168.25.23:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.26.25:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.29.142:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.29.144:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.16.233:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.17.106:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.17.107:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.17.30:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.19.213:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.19.214:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.19.215:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.19.217:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.19.218:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.19.220:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null } ], "Endpoints": null, "ServiceConfig": null, "Attributes": null} ()
2025-03-07T12:48:28.075	INFO	[core] [Channel #1 SubChannel #2]Subchannel picks a new address "192.168.19.220:443" to connect
2025-03-07T12:48:28.075	INFO	[pick-first-lb] [pick-first-lb 0xc000a37d70] Received new config { "shuffleAddressList": false}, resolver state { "Addresses": [ { "Addr": "192.168.25.23:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.26.25:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.29.142:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.29.144:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.16.233:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.17.106:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.17.107:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.17.30:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.19.213:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.19.214:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.19.215:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.19.217:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.19.218:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null }, { "Addr": "192.168.19.220:443", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null } ], "Endpoints": null, "ServiceConfig": null, "Attributes": null}
2025-03-07T12:48:28.075	INFO	[core] [Channel #1 SubChannel #2]addrConn: updateAddrs addrs (5 of 14): [{Addr: "192.168.25.23:443", ServerName: "", } {Addr: "192.168.26.25:443", ServerName: "", } {Addr: "192.168.29.142:443", ServerName: "", } {Addr: "192.168.29.144:443", ServerName: "", } {Addr: "192.168.16.233:443", ServerName: "", }]

see attached log, the relevant portion (reproduced above) starts at around PROBLEM MANIFESTS AROUND HERE text.

sample.2025-03-07.12-54-08.log.gz

the only unusual entry in the log that i see before this ResolveNow() infinite loop but don't normally find in the logs on any other net transients (which are handled gracefully) is this one (UPDATED): [core] blockingPicker: the picked transport is not ready, loop back to repick loopyWriter exiting with error: connection error: desc = "keepalive ping failed to receive ACK within timeout".

potentially relevant gRPC client options:

kal := keepalive.ClientParameters{
    Time:                10 * time.Second,
    Timeout:             10 * time.Second,
    PermitWithoutStream: true, 
}
dialBackoffConfig := backoff.Config{
    BaseDelay:  10 * time.Millisecond,
    Multiplier: 5,
    Jitter:     0.1,  
    MaxDelay:   3 * time.Second,
}
cp := grpc.ConnectParams{
    Backoff:           dialBackoffConfig,
    MinConnectTimeout: 1 * time.Second,
}
opts := []grpc.DialOption{
    grpc.WithBlock(),
    grpc.WithDisableRetry(),
    grpc.WithDefaultCallOptions(grpc.WaitForReady(true)),
    grpc.WithKeepaliveParams(kal),
    grpc.WithConnectParams(cp),
    grpc.WithResolvers(customResolver),
}

[purnesh42H]

@lev-lb are you using grpc.Dial or grpc.NewClient? If you have switched to grpc.NewClient which was released in 1.64, WithBlock parameter will be ignored. See release notes https://github.com/grpc/grpc-go/releases/tag/v1.64.0

From the logs I am seeing "operation was canceled" which means context cancelation by the caller either due to short timeout or manual cancelation. This is likely the cause of backoff not getting chance to execute and connection attempt being immediately aborted. If the cancelation happens during dialing the connection, all addresses are exhausted and clientconn is repored with TRANSIENT_FAILURE which triggers the reconnection process.

Its hard to debug further with just the logs. Could you provide your code showing how you are creating the client and how the cancelation is happening?

Also, do you have any back off implemented in your custom name resolver?

[lev-lb]

hi, @purnesh42H , thanks for looking into it.

@lev-lb are you using grpc.Dial or grpc.NewClient? If you have switched to grpc.NewClient which was released in 1.64, WithBlock parameter will be ignored.

the code in question still uses grpc.Dial(), but, but that's neither here nor there, the infinite loop happens hours after the initial Dial(), long after the initial connection has been established, lost, re-established, etc.

From the logs I am seeing "operation was canceled" which means context cancelation by the caller either due to short timeout or manual cancelation. This is likely the cause of backoff not getting chance to execute and connection attempt being immediately aborted. If the cancelation happens during dialing the connection, all addresses are exhausted and clientconn is repored with TRANSIENT_FAILURE which triggers the reconnection process.

all that is fine and by design: all the app-level calls are capped at ~10sec, and when the cluster is unreachable - it's expected that they will time out, and that the CC will go into TRANSIENT_FAILURE (among other things). the fact that reconnection process takes place is expected. the fact that gRPC core randomly attempts to call ResolveNow() to do this at the rate of over 15 thousand times per second is not expected.

i see nothing in the docs of the grpc.Dial() (or NewClient(), for that matter) options, including backoff and timeouts to indicate that the gRPC core will ever do that, nor do i see any logic in gRPC core trying to do that, especially since it did so only several times in the past months of 24/7 uptime, rather than every time.

Its hard to debug further with just the logs. Could you provide your code showing how you are creating the client and how the cancelation is happening?

see above: the cancellations are just plain vanilla gRPC call context timeouts. the gRPC client is created once, at app startup (i'm oversimplifying, but it's something that happens very rarely, say once a month). a client is expected to experience many CC state transients: some caused by app cluster server outages, some by network partitions. but also: some by app cluster servers closing connection, which they do after 60 sec of idle conn.

it is the latter flow that i suspect at the moment. AFAICT, this infinite ResolveNow() loop appears to coincide with the upstream gRPC server closing the conn (GOAWAY with no error, also reflected in the loopyWriter transport trace i mentioned above) just at the same time as the app is issuing a request on the gRPC client. coincidentally, the two sides have 60sec timers, one for closing the idle conn, the other for re-fetching some data once a minute. due to variable response timing, these coincide very rarely.

Also, do you have any back off implemented in your custom name resolver?

no. AFAICT - that would make it impossible for me to control the reconnection process to the cluster. i'm specifying the backoff and timeout params to the gRPC client itself (see reproduced in full above). as you can see, we need that reconnection to be relatively tight, time-wise, with rapid failover between the app cluster servers, one or more of which are extremely likely to be up at any given time. i have no control over when the gRPC core will call into ResolveNow(), so if gRPC core will actually follow its backoff/timeout config (which it does the overwhelming majority of time) and will call into the resolver which will introduce its own additional blocking delay, sometimes i'll end up with no delay, sometimes with compound delay of both, sometimes with a random mix of both. i need a deterministic backoff there.

[lev-lb]

Could you provide your code showing how you are creating the client and how the cancelation is happening?

@purnesh42H : actually, a very old version of the code is available online, client creation is here, cancellation is just the ctx timeout on individual gRPC calls.

the app currently experiencing the issue is closed-source, but the resolver+LB+client design is the same for all practical purposes. the timings used in the app linked above are different, i have reproduced the real config used now in the ticket above.

[lev-lb]

i had another repro today. so far, i can confirm that:

• this ResolveNow() loop appears to be consistently happening when the client happens to submit a new gRPC request just as the server is closing the connection on its side due to idle timeout.
  • it appears to be always preceded by some loopyWriter exiting with error trace, the most recent ones i'm seeing are received GOAWAY with no active streams. i might have been mistaken about the keepalive ping failed to receive ACK within timeout trace i initially pasted above in the text (the log snippet and the attached log were still correct, however). i'm guessing that just reflects the above point.
• not every loopyWriter exiting with error: received GOAWAY with no active streams trace leads to the death loop: in most cases gRPC core appears to recover nicely, as can be seen in the original log attached above.
• however, so far, every instance of the [core] blockingPicker: the picked transport is not ready, loop back to repick i've seen - was immediately followed by the death ResolveNow() loop, and every death loop that i have the logs for - immediately follows that trace.
• incidentally, only the client version was upgraded to v1.70.0. the server gRPC versions this issue has been observed with so far are probably v1.61.1, v1.63.2 and v1.66.0. no tests against v1.70.0 servers were carried out (nor are possible at present).

HTH.

[purnesh42H]

@lev-lb i am still trying to repro. Just to check, are you able to repro the same behavior when using dns resolver?