Idle timeout breaks xDS with go-control-plane

[Necropaw]

Background

In our project we are using the https://github.com/envoyproxy/go-control-plane with the xDS provider from https://github.com/wongnai/xds and grpc-java@v1.50.0 for client.

The client is communicating with multiple gRPC services on different hosts.

Current behavior

After the idle timeout of a channel (default: 30min) the xds client forgets resolved names.

The go-control-plane (and also the java-control-plane) are stateful and do not forget what the client requested, e.g.: https://github.com/envoyproxy/go-control-plane/blob/main/pkg/cache/v3/simple.go#L350

This leads to the following problem:

• client requests service-a, service-b, service-c and service-d on xds-resolver and gets a proper answer
• after the idle timeout things get shutdown for service-b:

"2022-10-18 @ 07:44:21.255",DEBUG,"grpc-default-worker-ELG-1-1","[xds-resolver<6>: (service-b)] Stop watching LDS resource service-b"
"2022-10-18 @ 07:44:21.255",DEBUG,"grpc-default-worker-ELG-1-1","[cluster_manager-lb<69>: (service-b)] Shutdown"
"2022-10-18 @ 07:44:21.255",DEBUG,"grpc-default-worker-ELG-1-1","[xds-resolver<6>: (service-b)] Shutdown"
"2022-10-18 @ 07:44:21.255",DEBUG,"grpc-default-worker-ELG-1-1","[xds-client<35>] Unsubscribing LDS resource service-b from server xds-resolver:1337"
"2022-10-18 @ 07:44:21.255",DEBUG,"grpc-default-worker-ELG-1-1","[cds-lb<70>: (service-b)] Shutdown"
"2022-10-18 @ 07:44:21.255",DEBUG,"grpc-default-worker-ELG-1-1","[xds-resolver<92>: (service-b)] Created resolver for service-b"
"2022-10-18 @ 07:44:21.256",DEBUG,"grpc-default-worker-ELG-1-1","[cluster-resolver-lb<71>: (service-b)] Stop watching EDS resource service-b.dev:grpc"
...
"2022-10-18 @ 07:44:21.256",DEBUG,"grpc-default-worker-ELG-1-1","[weighted-target-lb<75>: (service-b)] Shutdown"
"2022-10-18 @ 07:44:21.256",DEBUG,"grpc-default-worker-ELG-1-1","[cluster-resolver-lb<71>: (service-b)] Shutdown"
...
"2022-10-18 @ 07:44:21.256",DEBUG,"grpc-default-worker-ELG-1-1","[xds-client<35>] Unsubscribing EDS resource service-b.dev:grpc from server xds-resolver:1337"
"2022-10-18 @ 07:44:21.256",DEBUG,"grpc-default-worker-ELG-1-1","[priority-lb<72>: (service-b)] Shutdown"
"2022-10-18 @ 07:44:21.256",DEBUG,"grpc-default-worker-ELG-1-1","[xds-client<35>] Unsubscribing CDS resource service-b.dev:grpc from server xds-resolver:1337"
"2022-10-18 @ 07:44:21.256",TRACE,"grpc-default-worker-ELG-1-1","[priority-lb<72>: (service-b)] Priority deleted: service-b.dev:grpc[child1]"
"2022-10-18 @ 07:44:21.257",TRACE,"grpc-default-worker-ELG-1-1","[cluster_manager-lb<69>: (service-b)] Child balancer cluster:service-b.dev:grpc deleted"

• some time later the client wants to communicate with service-b again and tries to resolve it:

"2022-10-18 @ 08:05:33.361",DEBUG,"http-nio-8080-exec-5","[xds-resolver<92>: (service-b)] Start watching LDS resource service-b"
"2022-10-18 @ 08:05:33.361",TRACE,"http-nio-8080-exec-5","[xds-client<38>: (xds-resolver:1337)] Sent DiscoveryRequest
{
  ""versionInfo"": ""422bd1d65455a992"",
  ""node"": {
    ""id"": ""client-node-id"",
    ""userAgentName"": ""gRPC Java"",
    ""userAgentVersion"": ""1.50.0"",
    ""clientFeatures"": [""envoy.lb.does_not_support_overprovisioning"", ""xds.config.resource-in-sotw""]
  },
  ""resourceNames"": [""service-a"", ""service-b""],
  ""typeUrl"": ""type.googleapis.com/envoy.config.listener.v3.Listener"",
  ""responseNonce"": ""124""
}"
"2022-10-18 @ 08:05:33.361",DEBUG,"http-nio-8080-exec-5","[xds-client<35>] Subscribe io.grpc.xds.XdsListenerResource@74a2f92e resource service-b"
"2022-10-18 @ 08:05:33.361",DEBUG,"http-nio-8080-exec-5","[xds-client<38>: (xds-resolver:1337)] Sending LDS request for resources: [service-a, service-b]"
"2022-10-18 @ 08:05:46.369",DEBUG,"grpc-timer-0","[xds-client<35>] LDS resource service-b initial fetch timeout"
"2022-10-18 @ 08:05:46.369",DEBUG,"grpc-timer-0","[xds-client<35>] Conclude LDS resource service-b not exist"
"2022-10-18 @ 08:05:46.369",DEBUG,"grpc-timer-0","[xds-resolver<92>: (service-b)] LDS resource does not exist: service-b"

• this fails because the xDS provider remembered that this client already knows service-b in this version and just adds a watcher for possible upcoming changes:

"2022-10-18 @ 08:05:29.397",debug,"-","open watch 1528 for type.googleapis.com/envoy.config.listener.v3.Listener[service-a service-b] from nodeID """", version ""422bd1d65455a992"""
"2022-10-18 @ 08:05:29.397",debug,"-","nodeID """" requested type.googleapis.com/envoy.config.listener.v3.Listener[service-a service-b] and known map[service-c:{} service-d:{} service-a:{} service-b:{}]. Diff []"

At this stage the client can not communicate with the service anymore.

Workaround

Increase the idle timeout on the channel to some high value. In the hope the client wants to talk to it in this time frame.

Attachements

• full client log: client.csv

[chickenlj]

So one possible solution is for the client in this case grpc client to keep the copy of the last received information of service-b, is that right?

[Necropaw]

Yup, that would be one solution.

[ejona86]

@markdroth, what are your thoughts on this? It seems a channel goes idle due to inactivity and shuts down the NR and LBs, but the XdsClient is remaining alive and some resources are unsubscribed. After future activity, the channel reactivates but when it resubscribes to resources the XdsClient doesn't receive any resources because the control plane knows it sent them previously.

[markdroth]

What I think should happen in this case is:

1. The channel goes idle, so the xds resolver will tell the XdsClient to cancel its watch before the xds resolver is destroyed.
2. The XdsClient will see the last watch for a given resource has been cancelled, so it will send an unsubscription to the xDS server.
3. Later, when the channel exits idle, the new xds resolver will start a new watch on the XdsClient for the resource.
4. The XdsClient will notice that this is the first watch for the resource, so it will send a subscription to the xDS server.

At this point, the xDS server must resend the resource. It cannot decide not to resend the resource based on the fact that the client had seen the resource at some point in the past, because that was before the client unsubscribed from the resource. Once the client unsubscribes, it will no longer retain its cached copy of the resource, and the server must not assume that it has a cached copy.

If grpc-java is behaving correctly in terms of the steps above but go-control-plane is failing to resend the resource, then it's a bug in go-control-plane, not a bug in grpc-java.

[Necropaw]

Thanks for the clarification @markdroth and patience. I was ill and not able to respond.

Looking through the go-control-plane, grpc-java and https://www.envoyproxy.io/docs/envoy/latest/api-docs/xds_protocol there seems to be a difference in the interpretation how to process a "unsubscribe".

From the logs it is obvious:

• grpc-java: Sends a DiscoveryRequest with the removed resource(s), e.g.:

2022-10-18 @ 07:11:28.057, DEBUG, http-nio-8080-exec-6, [xds-client<38>: (xds-resolver:1337)] Sending LDS request for resources: [service-a, service-b, service-c]
2022-10-18 @ 07:44:24.259, DEBUG, grpc-default-worker-ELG-1-2, [xds-client<38>: (xds-resolver:1337)] Sending LDS request for resources: [service-a]

• go-control-plane: never sends a DiscoveryResponse with a nonce
• grpc-java: never ACK/NACKs with the correct nonce to update the requested resources (to trigger: https://github.com/envoyproxy/go-control-plane/blob/main/pkg/server/sotw/v3/server.go#L186)

Problem

In how the client specifies what resources to return an ACK/NACK is never mentioned, but in Resource Updats is the statement:

As discussed above, Envoy may update the list of resource_names it presents to the management server in each DiscoveryRequest that ACK/NACKs a specific DiscoveryResponse.

There are multiple scenarios now 🎉 :

• No ACK/NACK is needed -> error in go-control-plane for not updating correctly
• ACK/NACK is needed
  • go-control-plane needs to send a DiscoveryResponse in this case
  • grpc-java is not allowed to delete the resolved resources until it receives the DiscoveryResponse

This is beyond my knowledge and I would love some guidance.

[markdroth]

The client can change the list of subscribed resources in any request, even if that request is not an ACK/NACK. The sentence following the one you quoted above says:

In addition, Envoy may later issue additional DiscoveryRequests at a given version_info to update the management server with new resource hints.

The wording should probably be improved here, but "resource hints" refers to the resource_names field. So what this is saying is that the client can send a request with an updated list of resource names at any time, and that that change may or may not be in the same request as an ACK/NACK.

This seems like a go-control-plane bug to me. Once grpc-java sends a request with the removed resources, go-control-plane needs to honor that; it should not need any subsequent ACK/NACK. (It is fine for go-control-plane to not send another response after the unsubscription if none of the resources that the client is still subscribing to have changed.)

[Necropaw]

Well, then this can be closed.

Just my 2c regarding this protocol behavior: having a stateful client/server protocol where one party can change without acknowledgment from the other one, is very dangerous and in the best case scenario gRPC channel breaks, in the worst case (like here) a deadlock happens and can not be repaired. All thanks to a split-brain situation. Just splendid.

[markdroth]

I am actually not a big fan of the xDS SotW protocol, so in general I agree. In the future, I would like to see us move to the incremental protocol variant, which is much cleaner.

That having been said, I'm not sure that having acknowledgement of the subscription change at the protocol level would actually help here. If the server is going to violate the protocol spec, it can just as easily tell the client it's doing the right thing even when it's still doing the wrong thing.