xDS: v1.66.2 and above break most xDS client gRPC requests

[marcel808]

What version of gRPC are you using?

v1.65.0 works, 1.66.2/1.67.0 cause most gRPC xDS based requests to fail with error

rpc error: code = Unavailable desc = xds: error received from xDS stream: EOF

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

1.22.6

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

Linux (Google GKE)

What did you do?

We have go service pods that call out to other services using the istio agent (inject.istio.io/templates:a grpc-agent), prefix the service urls with "xds:///" and import _ "google.golang.org/grpc/xds".

istiod-1-22-4

What did you expect to see?

Succesfull gRPC requests load balanced using xDS

What did you see instead?

90% gRPC failure rate with error: rpc error: code = Unavailable desc = xds: error received from xDS stream: EOF

[easwars]

Would you be able to provide some logs for us? With the following env vars set: GRPC_GO_LOG_VERBOSITY_LEVEL=99 GRPC_GO_LOG_SEVERITY_LEVEL=info.

Thanks.

[easwars]

The error mentioned in the issue description happens when connection to the management server fails. https://github.com/grpc/grpc-go/blob/ca4865d6dd6f3d8b77f1943ccfd6c9e78223912d/xds/internal/xdsclient/authority.go#L462C1-L463C1

[marcel808]

I enabled grpc-go version 1.67.2 and here are the logs leading up to the error:

2024/10/03 16:01:45 INFO: [core] [Channel #26 SubChannel #27]Subchannel created
2024/10/03 16:01:45 INFO: [core] [Channel #26]Channel Connectivity change to CONNECTING
2024/10/03 16:01:45 INFO: [core] [Channel #26]Channel exiting idle mode
2024/10/03 16:01:45 INFO: [xds] [xds-client 0xc000bd8190] [unix:///etc/istio/proxy/XDS] Created transport to server "unix:///etc/istio/proxy/XDS"
2024/10/03 16:01:45 INFO: [xds] [xds-client 0xc000bd8190] [unix:///etc/istio/proxy/XDS] New watch for type "ListenerResource", resource name "<redacted>.svc.cluster.local:50051"
2024/10/03 16:01:45 INFO: [xds] [xds-client 0xc000bd8190] [unix:///etc/istio/proxy/XDS] First watch for type "ListenerResource", resource name "<redacted>.svc.cluster.local:50051"
2024/10/03 16:01:45 INFO: [core] [Channel #24]Channel exiting idle mode
2024/10/03 16:01:45 INFO: [core] [Channel #26 SubChannel #27]Subchannel Connectivity change to CONNECTING
2024/10/03 16:01:45 INFO: [core] [Channel #26 SubChannel #27]Subchannel picks a new address "/etc/istio/proxy/XDS" to connect
2024/10/03 16:01:45 INFO: [core] original dial target is: "xds:///<redacted>.svc.cluster.local:50052"
2024/10/03 16:01:45 INFO: [core] [Channel #28]Channel created
2024/10/03 16:01:45 INFO: [core] [Channel #28]parsed dial target is: resolver.Target{URL:url.URL{Scheme:"xds", Opaque:"", User:(*url.Userinfo)(nil), Host:"", Path:"/<redacted>.svc.cluster.local:50052", RawPath:"", OmitHost:false, ForceQuery:false, RawQuery:"", Fragment:"", RawFragment:""}}
2024/10/03 16:01:45 INFO: [core] [Channel #28]Channel authority set to "<redacted>.svc.cluster.local:50052"
2024/10/03 16:01:45 INFO: [pick-first-lb] [pick-first-lb 0xc000c1e240] Received SubConn state update: 0xc000c1e2a0, {ConnectivityState:CONNECTING ConnectionError:<nil> connectedAddress:{Addr: ServerName: Attributes:<nil> BalancerAttributes:<nil> Metadata:<nil>}}
2024/10/03 16:01:45 INFO: [core] connect called on addrConn in non-idle state (CONNECTING); ignoring.
2024/10/03 16:01:45 INFO: [xds] [xds-resolver 0xc000a74fc0] Creating resolver for target: xds:///<redacted>.svc.cluster.local:50052
2024/10/03 16:01:45 INFO: [xds] [xds-bootstrap] Using bootstrap file with name "/etc/istio/proxy/grpc-bootstrap.json" from GRPC_XDS_BOOTSTRAP environment variable
2024/10/03 16:01:45 INFO: [core] [Channel #26 SubChannel #27]Subchannel Connectivity change to READY
2024/10/03 16:01:45 INFO: [pick-first-lb] [pick-first-lb 0xc000c1e240] Received SubConn state update: 0xc000c1e2a0, {ConnectivityState:READY ConnectionError:<nil> connectedAddress:{Addr:/etc/istio/proxy/XDS ServerName:localhost Attributes:0xc00021a7a8 BalancerAttributes:<nil> Metadata:<nil>}}
2024/10/03 16:01:45 INFO: [core] [Channel #26]Channel Connectivity change to READY
2024/10/03 16:01:45 INFO: [xds] [xds-client 0xc000bd8190] [unix:///etc/istio/proxy/XDS] ADS stream created
2024/10/03 16:01:45 WARNING: [xds] [xds-client 0xc0001d7b80] [unix:///etc/istio/proxy/XDS] ADS stream closed: EOF
2024/10/03 16:01:45 INFO: [xds] [xds-resolver 0xc00072b440] Received error for Listener resource "<redacted>.cluster.local:8666": xds: error received from xDS stream: EOF
2024/10/03 16:01:45 WARNING: [core] [Channel #1]ccResolverWrapper: reporting error to cc: xds: error received from xDS stream: EOF

[marcel808]

vs 1.65.0:

2024/10/03 15:21:58 INFO: [xds] [xds-client 0xc0007fee10] [unix:///etc/istio/proxy/XDS] ADS stream created
2024/10/03 15:21:58 INFO: [xds] [xds-client 0xc0007fee10] [unix:///etc/istio/proxy/XDS] ADS request sent: {
"node":  {
"id":  "sidecar~<redacted>.cluster.local",

[easwars]

Thanks for the logs.

2024/10/03 16:01:45 WARNING: [xds] [xds-client 0xc0001d7b80] [unix:///etc/istio/proxy/XDS] ADS stream closed: EOF

The above line seem to indicate to me that the server is closing the stream for whatever reason. The above is logged when the xDS client runs into an error when attempting to read from the ADS stream.

[easwars]

Does your server logs contain anything useful?

[marcel808]

Could this be related (blanked out some of the ip parts)?

{"level":"warn","time":"2024-10-03T16:01:45.814940Z","scope":"ads","msg":"ADS: \"dd.dd.15.80:37586\" exceeded rate limit: context canceled"}
{"level":"warn","time":"2024-10-03T16:01:45.820678Z","scope":"ads","msg":"ADS: \"dd.dd.15.79:57722\" exceeded rate limit: context canceled"}
{"level":"warn","time":"2024-10-03T16:01:46.037482Z","scope":"ads","msg":"ADS: \"dd.dd.0.133:35194\" exceeded rate limit: context canceled"}
{"level":"warn","time":"2024-10-03T16:01:46.426842Z","scope":"ads","msg":"ADS: \"dd.dd.4.251:50008\" exceeded rate limit: context canceled"}
{"level":"warn","time":"2024-10-03T16:01:46.823614Z","scope":"ads","msg":"ADS: \"dd.dd.15.80:37612\" exceeded rate limit: context canceled"}
{"level":"warn","time":"2024-10-03T16:01:47.610846Z","scope":"ads","msg":"ADS: \"dd.dd.8.49:60104\" exceeded rate limit: context canceled"}
{"level":"warn","time":"2024-10-03T16:01:47.680695Z","scope":"ads","msg":"ADS: \"dd.dd.17.87:40414\" exceeded rate limit: context canceled"}
{"level":"warn","time":"2024-10-03T16:01:47.894435Z","scope":"ads","msg":"ADS: \"dd.dd.0.133:35212\" exceeded rate limit: context canceled"}
{"level":"warn","time":"2024-10-03T16:01:48.303335Z","scope":"ads","msg":"ADS: \"dd.dd.17.86:56104\" exceeded rate limit: context canceled"}
{"level":"warn","time":"2024-10-03T16:01:48.446480Z","scope":"ads","msg":"ADS: \"dd.dd.9.82:22297\" exceeded rate limit: context canceled"}
{"level":"warn","time":"2024-10-03T16:01:48.598658Z","scope":"ads","msg":"ADS: \"dd.dd.15.79:55362\" exceeded rate limit: context canceled"}
{"level":"warn","time":"2024-10-03T16:01:48.676814Z","scope":"ads","msg":"ADS: \"dd.dd.17.86:56120\" exceeded rate limit: context canceled"}
{"level":"warn","time":"2024-10-03T16:01:49.729190Z","scope":"ads","msg":"ADS: \"dd.dd.17.86:56146\" exceeded rate limit: context canceled"}
{"level":"warn","time":"2024-10-03T16:01:50.035842Z","scope":"ads","msg":"ADS: \"dd.dd.8.49:60114\" exceeded rate limit: context canceled"}
{"level":"warn","time":"2024-10-03T16:01:50.945518Z","scope":"ads","msg":"ADS: \"dd.dd.0.133:36854\" exceeded rate limit: context canceled"}
{"level":"warn","time":"2024-10-03T16:01:52.271491Z","scope":"ads","msg":"ADS: \"dd.dd.17.86:56196\" exceeded rate limit: context canceled"}
{"level":"warn","time":"2024-10-03T16:01:52.466689Z","scope":"ads","msg":"ADS: \"dd.dd.9.82:35128\" exceeded rate limit: context canceled"}
{"level":"warn","time":"2024-10-03T16:01:54.651522Z","scope":"ads","msg":"ADS: \"dd.dd.15.79:55434\" exceeded rate limit: context canceled"}
{"level":"warn","time":"2024-10-03T16:01:59.183774Z","scope":"ads","msg":"ADS: \"dd.dd.17.86:41806\" exceeded rate limit: context canceled"}
{"level":"warn","time":"2024-10-03T16:02:01.358069Z","scope":"ads","msg":"ADS: \"dd.dd.17.86:41826\" exceeded rate limit: context canceled"}
{"level":"warn","time":"2024-10-03T16:02:01.572871Z","scope":"ads","msg":"ADS: \"dd.dd.17.87:33432\" exceeded rate limit: context canceled"}
{"level":"warn","time":"2024-10-03T16:02:01.891733Z","scope":"ads","msg":"ADS: \"dd.dd.0.133:56666\" exceeded rate limit: context canceled"}

[easwars]

Interesting. Is this from your server?

But from the client logs, it seems like the client is not even sending one ADS request, right?

[marcel808]

Interesting. Is this from your server?
Yes, this is from kubectl logs -n istio-system istiod-....

But from the client logs, it seems like the client is not even sending one ADS request, right?

Seems like it since like it since the working version shows ADS request sent. I'll ask our infra structure team whether there are certain rate limits in play.
Note sure whether the rate limits are the cause of the EOF errors but they occur around the same time.
Any idea how the changes post 1.65 could have affected this?

[easwars]

Any idea how the changes post 1.65 could have affected this?

There were a few changes that could be of interest:

• xds: implement ADS stream flow control mechanism #7458: This change causes the xDS client to block further reads on the ADS stream until the previous update is completely processed locally
• xds: add support for multiple xDS clients, for fallback #7347: This change causes gRPC to create one xDS client per gRPC dial target. Earlier, there used to be single xDS client per gRPC binary. Now, if your binary makes multiple gRPC channels to different target URIs, you would have multiple xDS clients, one each for each target URI
  • This could cause more connections and more ADS streams on your server

[marcel808]

Thanks for the reference, I'll see also if the metric can located here that shows the ADS request rate to confirm there's a link to this issue.

[marcel808]

Adjusted the title as there might be some pods able to make requests. I will gather more information on the gRPC service and client pod counts.