During reconnection of Delta XDS subscription, some secrets are never requested

[howardjohn]

Title: During reconnection of Delta XDS subscription, some secrets are never requested

Description:
We are seeing a pretty subtle condition that occurs during our tests.

We have had the same test running without issues for years. We recently switched to using Delta XDS, and now see it somewhat frequently.

The test sets up an Envoy cluster with an SDS secret reference and sends requests. When the test fails, we see the cluster and secret "warming" in the config dump. In the control plane, we never get an SDS request for the resource.

This seems to happen when there is a disconnection from the control plane at just the right time. We have our XDS connections terminate semi-regularly.

Upon reconnection, envoy is requesting resources in an unusual order: EDS,LDS,RDS,SDS,CDS. I would typically see CDS first.

After the CDS request, there is no followup EDS request, which makes me suspicious that #13009 is coming into play. However, as far as I know, Envoy is supposed to send an EDS request here (see #13009 (comment), for prior analysis of the same issue)

Repro steps:
Unfortunately I do not have an isolated reproducer. I am reproducing it myself against Istio's test suite:

diff --git a/tests/integration/security/egress_gateway_origination_test.go b/tests/integration/security/egress_gateway_origination_test.go
index 6fed285b58..ca9328604a 100644
--- a/tests/integration/security/egress_gateway_origination_test.go
+++ b/tests/integration/security/egress_gateway_origination_test.go
@@ -19,8 +19,10 @@ package security
 
 import (
 	"fmt"
+	"math/rand"
 	"net/http"
 	"path"
+	"strconv"
 	"strings"
 	"testing"
 
@@ -117,6 +119,7 @@ func TestSimpleTlsOrigination(t *testing.T) {
 		})
 }
 
+
 // TestMutualTlsOrigination test MUTUAL TLS mode with TLS origination happening at Gateway proxy
 // It uses CredentialName set in DestinationRule API to fetch secrets from k8s API server
 func TestMutualTlsOrigination(t *testing.T) {
@@ -125,13 +128,13 @@ func TestMutualTlsOrigination(t *testing.T) {
 		RequiresSingleNetwork(). // https://github.com/istio/istio/issues/37134
 		Run(func(t framework.TestContext) {
 			var (
-				credNameGeneric    = "mtls-credential-generic"
-				credNameNotGeneric = "mtls-credential-not-generic"
-				fakeCredNameA      = "fake-mtls-credential-a"
-				credNameMissing    = "mtls-credential-not-created"
-				simpleCredName     = "tls-credential-simple-cacert"
-				credWithCRL        = "mtls-credential-crl"
-				credWithDummyCRL   = "mtls-credential-dummy-crl"
+				credNameGeneric    = "mtls-credential-generic-" + strconv.Itoa(int(rand.Int31()))
+				credNameNotGeneric = "mtls-credential-not-generic-" + strconv.Itoa(int(rand.Int31()))
+				fakeCredNameA      = "fake-mtls-credential-a-" + strconv.Itoa(int(rand.Int31()))
+				credNameMissing    = "mtls-credential-not-created-" + strconv.Itoa(int(rand.Int31()))
+				simpleCredName     = "tls-credential-simple-cacert-" + strconv.Itoa(int(rand.Int31()))
+				credWithCRL        = "mtls-credential-crl-" + strconv.Itoa(int(rand.Int31()))
+				credWithDummyCRL   = "mtls-credential-dummy-crl-" + strconv.Itoa(int(rand.Int31()))
 			)
 
 			// Add kubernetes secret to provision key/cert for gateway.

Change --keepaliveMaxServerConnectionAge=5s. Turn on debug logs.

./tests/integration/security -run TestMutualTlsOrigination -count 50 --failfast --istio.test.skipWorkloads=tproxy,vm

Config:
Here is an example config dump: https://storage.googleapis.com/istio-prow/logs/integ-ds_istio_postsubmit/1780583422448635904/artifacts/security-df00d96e40154f4688185d/TestMutualTlsOrigination/generic/a.echo1/to_external.external/_test_context/istio-state2391627172/primary-0/istio-egressgateway-75f47d8bd9-7bjfh_proxy-config.json. See the outbound|443||external.external-2-21010.svc.cluster.local warming cluster

Logs:

Log 1, just showing control plane view:

2024-04-17T13:44:07.204114Z     debug   delta   CDS: Send failure for node:istio-egressgateway-75f47d8bd9-7bjfh.istio-system resources:351 size:375.6kB cached:350/350
2024-04-17T13:44:07.877916Z     info    delta   ADS: "10.244.0.20:39290" istio-egressgateway-75f47d8bd9-7bjfh.istio-system-2 terminated
2024-04-17T13:44:07.953004Z     info    delta   ADS: new delta connection for node:istio-egressgateway-75f47d8bd9-7bjfh.istio-system-25
2024-04-17T13:44:07.953274Z     debug   delta   ADS:EDS: REQ istio-egressgateway-75f47d8bd9-7bjfh.istio-system-25 resources sub:350 unsub:0 nonce:
2024-04-17T13:44:07.954042Z     debug   delta   ADS:EDS REQUEST istio-egressgateway-75f47d8bd9-7bjfh.istio-system-25: sub:[outbound|15010||istiod.istio-system.svc.clu
2024-04-17T13:44:07.954128Z     debug   delta   ADS:EDS: RECONNECT istio-egressgateway-75f47d8bd9-7bjfh.istio-system-25  resources:350
2024-04-17T13:44:07.955774Z     info    delta   EDS: PUSH request for node:istio-egressgateway-75f47d8bd9-7bjfh.istio-system resources:350 removed:0 size:80.1kB empty
2024-04-17T13:44:07.955825Z     debug   delta   ADS:LDS: REQ istio-egressgateway-75f47d8bd9-7bjfh.istio-system-25 resources sub:0 unsub:0 nonce:
2024-04-17T13:44:07.955840Z     debug   delta   ADS:LDS REQUEST istio-egressgateway-75f47d8bd9-7bjfh.istio-system-25: sub:[] unsub:[] initial:map[0.0.0.0_8443:]
2024-04-17T13:44:07.955845Z     debug   delta   ADS:LDS: RECONNECT istio-egressgateway-75f47d8bd9-7bjfh.istio-system-25  resources:1
2024-04-17T13:44:07.956248Z     info    delta   LDS: PUSH request for node:istio-egressgateway-75f47d8bd9-7bjfh.istio-system resources:1 removed:0 size:3.9kB filtered
2024-04-17T13:44:07.956279Z     debug   delta   ADS:SDS: REQ istio-egressgateway-75f47d8bd9-7bjfh.istio-system-25 resources sub:2 unsub:0 nonce:
2024-04-17T13:44:07.956293Z     debug   delta   ADS:SDS REQUEST istio-egressgateway-75f47d8bd9-7bjfh.istio-system-25: sub:[kubernetes://fake-tls-credential-cacert kub
2024-04-17T13:44:07.956298Z     debug   delta   ADS:SDS: RECONNECT istio-egressgateway-75f47d8bd9-7bjfh.istio-system-25  resources:1
2024-04-17T13:44:07.956600Z     debug   delta   ADS:RDS: REQ istio-egressgateway-75f47d8bd9-7bjfh.istio-system-25 resources sub:1 unsub:0 nonce:
2024-04-17T13:44:07.956653Z     debug   delta   ADS:RDS REQUEST istio-egressgateway-75f47d8bd9-7bjfh.istio-system-25: sub:[https.443.https-sds.istio-egressgateway-sds
2024-04-17T13:44:07.956665Z     debug   delta   ADS:RDS: RECONNECT istio-egressgateway-75f47d8bd9-7bjfh.istio-system-25  resources:1
2024-04-17T13:44:07.956894Z     info    delta   RDS: PUSH request for node:istio-egressgateway-75f47d8bd9-7bjfh.istio-system resources:1 removed:0 size:467B cached:0/
2024-04-17T13:44:07.976229Z     debug   delta   ADS:EDS: REQ istio-egressgateway-75f47d8bd9-7bjfh.istio-system-25 resources sub:0 unsub:0 nonce:ed7c1347-9a6a-4ca5-af5
2024-04-17T13:44:07.976264Z     debug   delta   ADS:EDS REQUEST istio-egressgateway-75f47d8bd9-7bjfh.istio-system-25: sub:[] unsub:[] initial:map[]
2024-04-17T13:44:07.976348Z     debug   delta   ADS:EDS: ACK istio-egressgateway-75f47d8bd9-7bjfh.istio-system-25 ed7c1347-9a6a-4ca5-af52-ad9106a3565a
2024-04-17T13:44:07.976933Z     debug   delta   ADS:LDS: REQ istio-egressgateway-75f47d8bd9-7bjfh.istio-system-25 resources sub:0 unsub:0 nonce:1a90d6c1-54fc-4ba7-859
2024-04-17T13:44:07.976970Z     debug   delta   ADS:LDS REQUEST istio-egressgateway-75f47d8bd9-7bjfh.istio-system-25: sub:[] unsub:[] initial:map[]
2024-04-17T13:44:07.976980Z     debug   delta   ADS:LDS: ACK istio-egressgateway-75f47d8bd9-7bjfh.istio-system-25 1a90d6c1-54fc-4ba7-8590-e9a23a26f5af
2024-04-17T13:44:07.977204Z     debug   delta   ADS:RDS: REQ istio-egressgateway-75f47d8bd9-7bjfh.istio-system-25 resources sub:0 unsub:0 nonce:e141190a-509e-4881-8dc
2024-04-17T13:44:07.977255Z     debug   delta   ADS:RDS REQUEST istio-egressgateway-75f47d8bd9-7bjfh.istio-system-25: sub:[] unsub:[] initial:map[]
2024-04-17T13:44:07.977271Z     debug   delta   ADS:RDS: ACK istio-egressgateway-75f47d8bd9-7bjfh.istio-system-25 e141190a-509e-4881-8dcc-ba1b389b35a0
2024-04-17T13:44:21.452489Z     debug   delta   ADS:CDS: REQ istio-egressgateway-75f47d8bd9-7bjfh.istio-system-25 resources sub:0 unsub:0 nonce:
2024-04-17T13:44:21.453069Z     debug   delta   ADS:CDS REQUEST istio-egressgateway-75f47d8bd9-7bjfh.istio-system-25: sub:[] unsub:[] initial:map[BlackHoleCluster: ou
2024-04-17T13:44:21.453156Z     debug   delta   ADS:CDS: RECONNECT istio-egressgateway-75f47d8bd9-7bjfh.istio-system-25  resources:351
2024-04-17T13:44:21.455081Z     info    delta   CDS: PUSH request for node:istio-egressgateway-75f47d8bd9-7bjfh.istio-system resources:351 removed:0 size:375.6kB cach

---

Full debug logs with both control plane and data plane.
Timeline:

Istiod:
Last push 2024-04-17T15:13:18.866159Z, seems complete with SDS + ACK
Disconnect 2024-04-17T15:13:19.879595Z
Reconnect 2024-04-17T15:13:20.379661Z

Envoy:
2024-04-17T15:13:18.863599Z Gets SDS. `Create NotReadySslSocket` * many.
2024-04-17T15:13:18.865405Z xdsproxy sees SDS ack
2024-04-17T15:13:19.879699Z xdsproxy sees GOAWAY
2024-04-17T15:13:19.880044Z envoy sees GOAWAY. Listener, CLA, RDS, Secret, Cluster "failed"
2024-04-17T15:13:20.178973Z Still `Create NotReadySslSocket` coming in
2024-04-17T15:13:20.372790Z start new stream
2024-04-17T15:13:20.377399Z xdsproxy sees EDS,LDS,SDS,RDS requests
024-04-17T15:13:20.390831Z xdsproxy finally gets CDS request, between ACKs for the other types

envoy.txt
control.tar.gz

[adisuissa]

Thanks for reporting the issue, it does sound like a problem, and I wonder if we can get an AdsIntegrationTest that reproduces this bug.

The test sets up an Envoy cluster with an SDS secret reference and sends requests. When the test fails, we see the cluster and secret "warming" in the config dump. In the control plane, we never get an SDS request for the resource.

How long is the warming timeout configured in your case?

Upon reconnection, envoy is requesting resources in an unusual order: EDS,LDS,RDS,SDS,CDS. I would typically see CDS first.

Are you using ADS? If so the order should be fixed.
To the best of my understanding the order is dependent on the original bootstrap config order. For example, if there are clusters defined in the bootstrap that are of EDS type, that will be sent before the CDS request.

After the CDS request, there is no followup EDS request, which makes me suspicious that #13009 is coming into play. However, as far as I know, Envoy is supposed to send an EDS request here (see #13009 (comment), for prior analysis of the same issue)

Sending a request for a known EDS is the current (somewhat wrong if you look at the xDS-protocol) behavior for SotW, but not for delta. If you think of it as a PubSub protocol, Envoy already subscribed to the resource, so no need to send the same subscription again. Specifically for EDS, we now have a cache (guarded by this) that "solves" #13009.
A similar cache will later on be used for the rest of the xDS types.

[howardjohn]

How long is the warming timeout configured in your case?
For EDS, infinite. For SDS, 15s (unset; default is 15s)..

Are you using ADS? If so the order should be fixed.
To the best of my understanding the order is dependent on the original bootstrap config order. For example, if there are clusters defined in the bootstrap that are of EDS type, that will be sent before the CDS request.

We do use ADS. I was a bit surprised by this as well, but in theory its fine for us. See #13009 (comment) for prior discussion.

Note the difference now and then is that Envoy is not sending followup EDS request after CDS (was EDS->CDS->EDS, now EDS->CDS without EDS). Before vs after is likely SotW vs Delta.

Specifically for EDS, we now have a cache

We did have this on for a while, but ended up reverting in istio/istio#49801. I can maybe try to see if it impacts this issue at all.

[adisuissa]

Note the difference now and then is that Envoy is not sending followup EDS request after CDS (was EDS->CDS->EDS, now EDS->CDS without EDS). Before vs after is likely SotW vs Delta.

This is WAI, as it is up to the server to send that EDS without the client requesting it.

[adisuissa]

But I do wonder about the order of these requests after reconnection, because I thought there was code that intentionally required these to be used. That said, it shouldn't matter (in theory).

If you have infinite timeout for EDS, then the cache won't work for you, and then you will probably have a problem here.
There were some discussions around making Envoy adhere to the protocol, however it may break some use-cases.
Specifically, Envoy cannot know whether a CDS update requires a new EDS assignment or not (say the cluster moved from non-TLS to TLS). That's why the compromise was to wait for an EDS update (up until the timeout), and if no new EDS update arrived, use the cached EDS assignment.

[howardjohn]

So with SotW, it would normally be CDS->EDS. This works fine of course. When we do spontaneous pushes, we always do CDS+EDS together.

The edge case was when it would oddly send EDS first. Originally, it would send EDS -> CDS -> EDS, and the 2nd EDS we would classify as an ACK (no change in request, we already sent everything). Our workaround was to always respond to EDS request after a CDS request.

With the move to Delta, we no longer see that. We just get EDS -> CDS. So maybe now we should just spontaneously push EDS again after a CDS request if we already saw an EDS request.

Or change envoy to always send CDS first, I suppose

[adisuissa]

So with SotW, it would normally be CDS->EDS. This works fine of course. When we do spontaneous pushes, we always do CDS+EDS together.

The edge case was when it would oddly send EDS first. Originally, it would send EDS -> CDS -> EDS, and the 2nd EDS we would classify as an ACK (no change in request, we already sent everything). Our workaround was to always respond to EDS request after a CDS request.

It's not a problem if you use the EDS cache and some timeout.
On the first EDS response it will cache the resources. When the CDS response will arrive it will create the clusters (warming mode). After the timeout it will take the assignment from the cache.

With the move to Delta, we no longer see that. We just get EDS -> CDS. So maybe now we should just spontaneously push EDS again after a CDS request if we already saw an EDS request.

The idea was to wait for the timeout, and then use the cached version.
Can you change the timeout?

Or change envoy to always send CDS first, I suppose

IMHO it would be better to keep the original order if possible.
Note, however, that this may not always work as one would expect.
Example: say Envoy is configured with a (bootstrap-defined) EDS cluster, and a CDS wildcard.
On startup Envoy will first send the EDS request (for that single cluster), then send a CDS request, then send the EDS for the rest of the clusters.

On reconnection, Envoy sees the order as EDS then CDS, so it will be reverted...

[howardjohn]

I don't think we will never change the timeout. I don't think the behavior with a timeout is acceptable. Its either too high and causes updates to take too long, or too low and doesn't allow the server to be temporarily slow. For us, forever warming is the correct behavior if we are just waiting on a slower xds server.

We don't use EDS static clusters fwiw