Race condition or reordering of jobs during startup causes loss of L3 ports

[horazont]

Look at the following log (redacted for reasons, but the key idea is visible). I cut it into snippets to point at the various code places we're at.

W0621 08:49:17.637865       1 client_config.go:617] Neither --kubeconfig nor --master was specified.  Using the inClusterConfig.  This might not work.
I0621 08:49:18.750799       1 controller.go:113] Setting up event handlers
I0621 08:49:18.752439       1 controller.go:182] Starting Load Balancer controller
I0621 08:49:18.757767       1 controller.go:185] Waiting for informer caches to sync

controller.go:185

At this point, we get a full initial sync and are presented with the list of service objects:

I0621 08:49:18.837646       1 controller.go:224] handleObject called
I0621 08:49:18.837667       1 controller.go:229] Processing object: monitoring/prometheus-stack-prometheus-node-exporter
[…]
I0621 08:49:18.841761       1 controller.go:229] Processing object: monitoring/prometheus-adapter
I0621 08:49:18.842126       1 controller.go:224] handleObject called
[…]
I0621 08:49:18.840476       1 controller.go:224] handleObject called
I0621 08:49:18.840516       1 controller.go:229] Processing object: k8s-svc-ingress/ingress-ingress-nginx-controller-admission
[…]
I0621 08:49:18.930515       1 controller.go:224] handleObject called
I0621 08:49:18.930578       1 controller.go:229] Processing object: k8s-svc-ingress/ingress-ingress-nginx-controller

controller.go:229

These all cause SyncServiceJob instances to be enqueued. Then the sync is eventually over:

I0621 08:49:18.932766       1 controller.go:224] handleObject called
I0621 08:49:18.932808       1 controller.go:229] Processing object: kube-system/ch-k8s-lbaas-controller
I0621 08:49:18.930315       1 controller.go:193] Starting workers

Starting workers is right after we enqueued the RemoveCleanupBarrier.

I0621 08:49:18.932896       1 controller.go:204] Started workers
I0621 08:49:18.932944       1 controller.go:212] Triggering periodic cleanup
I0621 08:49:18.933026       1 worker.go:277] Worker started
I0621 08:49:25.401770       1 worker.go:306] Successfully executed job UpdateConfigJob
I0621 08:49:25.401879       1 worker.go:306] Successfully executed job SyncServiceJob("monitoring/prometheus-stack-prometheus-node-exporter")
[…]
I0621 08:49:25.404497       1 worker.go:306] Successfully executed job SyncServiceJob("monitoring/prometheus-adapter")
I0621 08:49:25.404634       1 worker.go:306] Successfully executed job RemoveCleanupBarrier
I0621 08:49:25.680933       1 port_manager.go:239] Used ports=[]
I0621 08:49:25.681074       1 port_manager.go:255] Trying to delete port "90bc1474-e1ed-4d58-87b7-3d281ff0a191"
I0621 08:49:28.298263       1 port_manager.go:224] Trying to delete floating ip "5b0463e4-7c70-4c66-af46-6f2a204c8032"
I0621 08:49:29.162748       1 worker.go:306] Successfully executed job CleanupJob
I0621 08:49:29.163014       1 worker.go:306] Successfully executed job SyncServiceJob("k8s-svc-cert-manager/cert-manager-webhook")
I0621 08:49:29.163298       1 port_mapper.go:209] Lookup l3port[90bc1474-e1ed-4d58-87b7-3d281ff0a191]={map[]}
I0621 08:49:29.163464       1 port_mapper.go:211] Allocating port {TCP 80} to service k8s-svc-ingress/ingress-ingress-nginx-controller
I0621 08:49:29.163802       1 port_mapper.go:211] Allocating port {TCP 443} to service k8s-svc-ingress/ingress-ingress-nginx-controller
E0621 08:49:29.241823       1 worker.go:330] error processing job SyncServiceJob("k8s-svc-ingress/ingress-ingress-nginx-controller"): Resource not found: [GET https://network-f1a.cloudandheat.com:9696/v2.0/ports/90bc1474-e1ed-4d58-87b7-3d281ff0a191], error message: {"NeutronError": {"type": "PortNotFound", "message": "Port 90bc1474-e1ed-4d58-87b7-3d281ff0a191 could not be found.", "detail": ""}}; requeueing

And here we can observe what goes wrong. After monitoring/prometheus-adapter is synced, the RemoveCleanupBarrier is executed, but before the k8s-svc-ingress/ingress-ingress-nginx-controller service is synced even once!

That way, the CleanupJob does not see the usage of the L3 port used by that service and it deletes it. Later on, when the service is synced, ch-k8s-lbaas tries to use the port and fails hard because it doesn't exit.

That breaks one of the fundamental assumptions in ch-k8s-lbaas, namely that all services are synced at least once before RemoveCleanupBarrier is invoked (and thus before the first CleanupJob can run).

The question is now why this happens. I could imagine multiple scenarios:

• There is a race condition which is not observable in the logs which causes cache.WaitForCacheSync to return early, hence RemoveCleanupBarrierJob being enqueued too early.
• The queue itself has somewhat unstable ordering (conceivable, because it also does job deduplication; maybe something is weird with the hashes?).

Either way, this needs more investigation and fixing. A workaround could involve not enqueueing a CleanupJob initially (only the barrier removal), causing it to be delayed by 17s (due to controller.go:202).