wait for cache sync and DAG build before starting xDS server

[therealak12]

Closes #5550.
Closes #1280.

I've removed the x.mgr.GetCache().WaitForCacheSync() call as it's implicitly handled in the mgr.Start() flow.

As a TLDR, the PR prevents starting the XDS server and building the DAG until the cache is synced with the initial list of k8s objects.

[codecov]

Codecov Report

Merging #5672 (d6881e7) into main (b865f33) will decrease coverage by 0.08%.
Report is 6 commits behind head on main.
The diff coverage is 30.76%.

Additional details and impacted files

@@            Coverage Diff             @@
##             main    #5672      +/-   ##
==========================================
- Coverage   78.59%   78.52%   -0.08%     
==========================================
  Files         138      138              
  Lines       19244    19299      +55     
==========================================
+ Hits        15125    15154      +29     
- Misses       3830     3853      +23     
- Partials      289      292       +3     

Files	Coverage Δ
internal/featuretests/v3/featuretests.go	86.60% <100.00%> (-0.05%)	⬇️
internal/contour/handler.go	82.16% <61.29%> (-6.07%)	⬇️
cmd/contour/serve.go	19.82% <0.00%> (-0.31%)	⬇️

... and 1 file with indirect coverage changes

[therealak12]

There's actually a better way to implement this. The server should only wait for the first DAG build. The handler itself then would ensure the first DAG build is done after the cache sync.

I'll push a commit to implement this.

[tsaarni]

Nice work @therealak12!

So, my understanding from this is that WaitForCacheSync() might have worked - if we did NOT process the events asynchronously. Since client-go will be unaware of our background processing it returns while we still process our own queue. For this kind of situations, client-go offers utility SingleFileTracker, where user signals their async processing by using Start() and Finished() call-pair per resource in initial list, and HasSynced() which additionally covers the initial queue inside client.go. Is that correct?

I added some small questions inline as well.

The change makes sense to me and seems to work on my machine as well 🙂 👍

Would you add a changelog entry as well?

[therealak12]

Nice work @therealak12!

So, my understanding from this is that WaitForCacheSync() might have worked - if we did NOT process the events asynchronously. Since client-go will be unaware of our background processing it returns while we still process our own queue. For this kind of situations, client-go offers utility SingleFileTracker, where user signals their async processing by using Start() and Finished() call-pair per resource in initial list, and HasSynced() which additionally covers the initial queue inside client.go. Is that correct?

I added some small questions inline as well.

The change makes sense to me and seems to work on my machine as well 🙂 👍

Would you add a changelog entry as well?

Thanks for your review and comments. I try to explain what happens exactly:

• The manager's WaitForCacheSync waits until the initial list of Kubernetes objects is delivered to the informers.
• We register our handlers to these informers and ignore the returned HasSynced methods.
• Although the full list of initial objects exists in the informers, they're not necessarily handled by the contour handler and thus they don't necessarily exist in the contour's internal cache.
• The DAG rebuild goroutine starts rebuilding DAG and updating Ingress objects based on its own cache

This PR waits until all of the HasSynced methods that are received when registering handlers, return true, and then starts the DAG rebuild process.

Those HasSynced methods would return true when OnAdd method of the handler is called for all of the objects in the initial list. If we only rely on these HasSynced methods, we may start DAG rebuild process before putting the last object in the cache! (The last object because we use an unbuffered channel and thus OnAdd is blocked until the current object is read by the goroutine.)

This is why I've used the SingleFileTracker. It's decremented each time the OnAdd is called for an object of the initial list and incremented when its handling is done. So if syncTracker.HasSynced returns true, it means we are not processing any objects at that moment.

[tsaarni]

I have one more observation, but otherwise the change looks good to me 👍

Assume we have a lot of resources that require status update, let's say 2000 HTTPProxies with status marked as invalid, and the status now needs to be updated valid at once, because the error condition was fixed during Contour was down.

There seems to be a chance now, that Contour will NOT start XDS server before the statuses have been pushed to Kubernetes. It happens like following:

Sometimes Contour manages to acquire lease before client-go sync has finalised. StatusUpdateHandler will get started and processing status updates is enabled:

time="2023-08-25T14:16:15+03:00" level=info msg="attempting to acquire leader lease projectcontour/leader-elect...\n" caller="leaderelection.go:245" context=kubernetes
time="2023-08-25T14:16:15+03:00" level=info msg="successfully acquired lease projectcontour/leader-elect\n" caller="leaderelection.go:255" context=kubernetes
time="2023-08-25T14:16:15+03:00" level=info msg="started status update handler" context=StatusUpdateHandler
time="2023-08-25T14:16:15+03:00" level=info msg="received a new address for status.loadBalancer" context=loadBalancerStatusWriter loadbalancer-address=
time="2023-08-25T14:16:15+03:00" level=info msg="performing delayed update" context=contourEventHandler last_update=239.3048ms outstanding=3984

In this case the processing of status updates happens within rebuildDAG() before we have set e.initialDagBuilt = true. Due to the default client rate limits (adjustable by --kubernetes-client-qps and --kubernetes-client-burst) the XDS server will be down for quite a while, depending on how many statuses there are to update.

In my test it took 7 minutes to update 2000 HTTPProxies until I got this:

time="2023-08-25T14:22:33+03:00" level=info msg="the initial dag is built" context=xds
time="2023-08-25T14:22:33+03:00" level=info msg="started xDS server type: \"contour\"" address="0.0.0.0:8001" context=xds

Since the XDS server does not depend on statuses, I think it would make sense to set initialDagBuilt = True to start XDS server before looping and sending the status updates:

contour/internal/contour/handler.go

Lines 243 to 250 in 68bafab

	func (e *EventHandler) rebuildDAG() {
	latestDAG := e.builder.Build()
	e.observer.OnChange(latestDAG)
	for _, upd := range latestDAG.StatusCache.GetStatusUpdates() {
	e.statusUpdater.Send(upd)
	}
	}

Cc @sunjayBhatia, @skriss

[therealak12]

I have one more observation, but otherwise the change looks good to me 👍

Assume we have a lot of resources that require status update, let's say 2000 HTTPProxies with status marked as invalid, and the status now needs to be updated valid at once, because the error condition was fixed during Contour was down.

There seems to be a chance now, that Contour will NOT start XDS server before the statuses have been pushed to Kubernetes. It happens like following:

Sometimes Contour manages to acquire lease before client-go sync has finalised. StatusUpdateHandler will get started and processing status updates is enabled:

time="2023-08-25T14:16:15+03:00" level=info msg="attempting to acquire leader lease projectcontour/leader-elect...\n" caller="leaderelection.go:245" context=kubernetes
time="2023-08-25T14:16:15+03:00" level=info msg="successfully acquired lease projectcontour/leader-elect\n" caller="leaderelection.go:255" context=kubernetes
time="2023-08-25T14:16:15+03:00" level=info msg="started status update handler" context=StatusUpdateHandler
time="2023-08-25T14:16:15+03:00" level=info msg="received a new address for status.loadBalancer" context=loadBalancerStatusWriter loadbalancer-address=
time="2023-08-25T14:16:15+03:00" level=info msg="performing delayed update" context=contourEventHandler last_update=239.3048ms outstanding=3984

In this case the processing of status updates happens within rebuildDAG() before we have set e.initialDagBuilt = true. Due to the default client rate limits (adjustable by --kubernetes-client-qps and --kubernetes-client-burst) the XDS server will be down for quite a while, depending on how many statuses there are to update.

In my test it took 7 minutes to update 2000 HTTPProxies until I got this:

time="2023-08-25T14:22:33+03:00" level=info msg="the initial dag is built" context=xds
time="2023-08-25T14:22:33+03:00" level=info msg="started xDS server type: \"contour\"" address="0.0.0.0:8001" context=xds

Since the XDS server does not depend on statuses, I think it would make sense to set initialDagBuilt = True to start XDS server before looping and sending the status updates:

contour/internal/contour/handler.go

Lines 243 to 250 in 68bafab

	func (e *EventHandler) rebuildDAG() {
	latestDAG := e.builder.Build()
	e.observer.OnChange(latestDAG)
	for _, upd := range latestDAG.StatusCache.GetStatusUpdates() {
	e.statusUpdater.Send(upd)
	}
	}

Cc @sunjayBhatia, @skriss

If I've understood correctly, you mean we should allow status updates regardless of whether the cache is synced or not. (Please correct me if I'm wrong)

We have about 3000 httpproxy objects. They all use a delegated certificate. After a restart, if contour puts the TLSCertificateDelegation resource in its cache after the httpproxy objects, it marks all valid httpproxies as invalid! This is what triggered us to make this PR to wait for the full cache sync before starting XDS server, DAG rebuild, etc.

[tsaarni]

If I've understood correctly, you mean we should allow status updates regardless of whether the cache is synced or not. (Please correct me if I'm wrong)

No, we should wait for cache sync before status updates are started. However, the problem is that rebuildDAG() can still take minutes just to update the statuses, and during that time (in the scenario above) Envoys are not being served their configuration by Contour, since starting of XDS server (initialDagBuilt = True) is delayed until the function returns. Updating the status is slow background process, and I think we could already start the XDS server when the status update is going on.

If Envoys restart during Contour restart, Contour would be up and serving configuration in few hundred msecs (=time of sync) instead of few minutes (time of status update).

Even though the status updates are sent via a channel to be processed asynchronously, I think the channel itself blocks when we have enough updates and that is why statusUpdater.Send() inside rebuildDAG() blocks.

[tsaarni]

Thank you @therealak12, this looks good to me! 🙏

Waiting for @skriss and @sunjayBhatia to take a look as well.

[skriss]

LGTM, thanks again @therealak12! Will leave open for a bit in case anyone else wants to look, but we'll definitely plan to get this into the upcoming 1.27 release.

[sunjayBhatia]

Looks good overall, just one requested change on the mechanism for signaling between goroutines that the race detector picks up

It might be good to add a run of the e2es where we add the -race flag when contour is compiled so we catch these sorts of things, can do as a daily build or even just enable for all runs by default

[clayton-gonsalves]

lgtm, modulo a few nits