arjan-bal
commented
1 month ago Before each of the error logs, the listener resource for iam-machine-api.auth isn't found (maybe the servers restarted?). This is causing an empty resolver state to be created which results in the creation of a pickfirst leaf LB policy which is the default LB policy when none is specified. pickfirst is given the empty endpoint list and it logs the error we're seeing.
2024/09/12 07:38:25 INFO: [xds] [xds-resolver 0xc00918f320] Received resource-not-found-error for Listener resource "iam-machine-api.auth:5000"
2024/09/12 07:38:25 INFO: [xds] [xds-client 0xc0091edd10] [semaphore-xds.sys-semaphore.svc.cluster.local:18000] ADS request sent: {
"versionInfo": "1789713",
"resourceNames": [
"iam-machine-api.auth:5000"
],
"typeUrl": "type.googleapis.com/envoy.config.listener.v3.Listener",
"responseNonce": "1538097"
}
2024/09/12 07:38:25 INFO: [xds] [xds-resolver 0xc00918f320] For Listener resource "iam-machine-api.auth:5000" and RouteConfiguration resource "", generated service config: {
"loadBalancingConfig": [
{
"xds_cluster_manager_experimental": {
"children": {
"cluster:iam-machine-api.auth.5000": {
"childPolicy": [
{
"cds_experimental": {
"cluster": "iam-machine-api.auth.5000"
}
}
]
}
}
}
}
]
}
2024/09/12 07:38:25 INFO: [core] [Channel #9]Resolver state updated: {
"Addresses": null,
"Endpoints": [],
"ServiceConfig": {
"Config": {
"Config": null,
"Methods": {}
},
"Err": null
},
"Attributes": {
"\u003c%!p(resolver.csKeyType=grpc.internal.resolver.configSelector)\u003e": "\u003c0x0\u003e",
"\u003c%!p(xdsclient.clientKeyType=grpc.xds.internal.client.Client)\u003e": "\u003c0xc007d369b0\u003e"
}
} ()
2024/09/12 07:38:25 INFO: [xds] [xds-cluster-manager-lb 0xc02deeda00] Update with config {
"LoadBalancingConfig": null,
"Children": {
"cluster:iam-machine-api.auth.5000": {
"ChildPolicy": [
{
"cds_experimental": {
"LoadBalancingConfig": null,
"Cluster": "iam-machine-api.auth.5000"
}
}
]
}
}
}, resolver state {Addresses:[] Endpoints:[] ServiceConfig:0xc02fff8580 Attributes:{"<%!p(resolver.csKeyType=grpc.internal.resolver.configSelector)>": "<0x0>" , "<%!p(xdsclient.clientKeyType=grpc.xds.internal.client.Client)>": "<0xc007d369b0>" }}
2024/09/12 07:38:25 INFO: [xds] [cds-lb 0xc02f3cc9c0] Received balancer config update: {
"LoadBalancingConfig": null,
"Cluster": "iam-machine-api.auth.5000"
}
2024/09/12 07:38:25 INFO: [core] [Channel #9]Resolver state updated: {
"Addresses": null,
"Endpoints": [],
"ServiceConfig": {
"Config": {
"Config": null,
"Methods": {}
},
"Err": null
},
"Attributes": null
} (service config updated)
2024/09/12 07:38:25 INFO: [core] [Channel #9]Channel switches to new LB policy "pick_first"
2024/09/12 07:38:25 INFO: [pick-first-lb] [pick-first-lb 0xc02fffbda0] Received error from the name resolver: produced zero addresses
2024/09/12 07:38:25 INFO: [core] [Channel #9]Channel Connectivity change to TRANSIENT_FAILURE
2024/09/12 07:38:25 INFO: [core] error from balancer.UpdateClientConnState: bad resolver stateOnce the listener becomes available, pickfirst is removed. Still looking into whether anything changed about the handling of not found listeners in 1.66 which would cause these logs to show up.
rcrowe
ffilippopoulos
easwars
purnesh42H
What version of gRPC are you using?
v.1.66.0What version of Go are you using (
go version)?1.22.5What operating system (Linux, Windows, …) and version?
Alpine 3.14K8s v1.30.1What did you do?
Ran
v.1.66.0across a fleet of gRPC clients & servers, using xDS to talk to an in-house control plane.xDS services configured with
round_robinload-balancer.Logs captured with:
GRPC_GO_LOG_VERBOSITY_LEVEL=99GRPC_GO_LOG_SEVERITY_LEVEL=infoWhat did you expect to see?
Running
v1.65.0we observe no such errors in with our clients talking to our servers.What did you see instead?
A % of requests will see...
We observe the errors happening multiple times per-minute, for a few minutes & then the errors will drop for up to 5 minutes. It's frequent enough to reliably replicate the problem across all our environments should you need us to capture more information.
I've not yet understood the pattern of when it fails & how often, but have attached logs.tar.gz from a small timeframe when we observed multiple errors, for a single container.
We were focused on the falling calls to
iam-policy-decision-api.auth:5000during our debugging & by querying against our trace backend, observed the following timestamps where these errors occurred. Note logs are in UTC while traces bellow are in BST (UTC+1).