Cluster-api-provider-azure: MachinePool takes 15 minutes to come online

[chewong]

/kind bug

What steps did you take and what happened:
[A clear and concise description of what the bug is.]

MachinePool takes around 15 minutes after the control plane is Ready to come online.

I create the cluster with ./hack/create-dev-cluster.sh with CLUSTER_TEMPLATE=./templates/cluster-template-machinepool.yaml

kubectl get nodes:

NAME                              STATUS   ROLES    AGE   VERSION
capz-uupdcg-control-plane-2njvp   Ready    master   32m   v1.17.4
capz-uupdcg-mp-0000001            Ready    <none>   16m   v1.17.4
capz-uupdcg-mp-0000003            Ready    <none>   16m   v1.17.4

kubectl logs capz-controller-manager-7f47f468f8-k6blr -n capz-system -c manager | grep MachinePool > machinepool.log: machinepool.log

What did you expect to happen:

It should take less than 15 minutes for the MachinePool to come online.

Anything else you would like to add:
[Miscellaneous information that will assist in solving the issue.]

Environment:

• cluster-api-provider-azure version: master
• Kubernetes version: (use kubectl version):
• OS (e.g. from /etc/os-release):

[CecileRobertMichon]

This is what I'm observing while waiting:

• AzureMachinePool controller loops on "Bootstrap data secret reference is not yet available"

[manager] I0602 01:02:18.221410      35 azuremachinepool_controller.go:213] controllers/AzureMachinePool "msg"="Bootstrap data secret reference is not yet available" "AzureCluster"="capz-vmss" "azureMachinePool"="capz-vmss-mp-0" "cluster"="capz-vmss" "machinePool"="capz-vmss-mp-0" "namespace"="default" 

• MachinePool is in pending phase

 kubectl get mp
NAME                      PHASE
capz-vmss-mp-0            Pending

• AzureMachinePool has no replicas

kubectl get amp                                                                                               
NAME                      REPLICAS   READY   STATE
capz-vmss-mp-0

[CecileRobertMichon]

Once MachinePool goes to provisioning, it only takes a few minutes for the Azure scale set to be created and the nodes to show up in the cluster... I think this might be an issue in the CAPI MachinePool controller.

[CecileRobertMichon]

Also it didn't take 15 minutes for the vmss replicas to come up but definitely took a while, only ~3.5 minutes between the last control-plane and the first vmss node here:

kubectl --kubeconfig=./kubeconfig get nodes                
NAME                            STATUS   ROLES    AGE     VERSION
capz-vmss-control-plane-nq9wx   Ready    master   8m27s   v1.17.5
capz-vmss-control-plane-nzkn4   Ready    master   10m     v1.17.5
capz-vmss-control-plane-w8hrv   Ready    master   5m50s   v1.17.5
capz-vmss-mp-0000000            Ready    <none>   2m4s    v1.17.5
capz-vmss-mp-0000002            Ready    <none>   2m16s   v1.17.5

[CecileRobertMichon]

This seems to vary, in some cases the vmss nodes come up under 5 minutes:

NAME                              STATUS   ROLES    AGE     VERSION
capz-vmss-3-control-plane-ccbss   Ready    master   5m4s    v1.17.5
capz-vmss-3-control-plane-r7wdg   Ready    master   46s     v1.17.5
capz-vmss-3-control-plane-rj5nn   Ready    master   3m26s   v1.17.5
capz-vmss-3-mp-0000002            Ready    <none>   2m25s   v1.17.5
capz-vmss-3-mp-0000003            Ready    <none>   2m23s   v1.17.5

[alexeldeib]

I haven’t looked closely but I’m curious if it’s possible something is missing a mapped watch in CAPI so it doesn’t get reconciled right away when it should? And the difference in times is due to backoff/requeue whenever it happens to hit

[chewong]

Could you try creating a cluster with 1 control plane machine instead of 3?

[CecileRobertMichon]

/priority important-soon

[CecileRobertMichon]

/assign

[CecileRobertMichon]

I don't have time to look at this right now, unassign in case someone else wants to take it.

/unassign

[detiber]

I believe part of this is related to some of the watch/predicate changes that are being implemented here: https://github.com/kubernetes-sigs/cluster-api-provider-azure/pull/691

[devigned]

@detiber, I don't think I understand how the open PR is related to the delay in machine pools. Are you saying that the watch / predicate changes in CAPI for pause are affecting the time to reconcile machine pools?

[detiber]

@devigned correct, it's not currently getting a reconciliation request when the Cluster infrastructure becomes ready and likely gets stuck either in exponential backoff or hitting the retry limit and has to wait on resync interval to re-reconcile.

That said, I'm also now wondering if we need common Watch/predicate handling for watching and triggering a reconciliation when a ControlPlane provider becomes "available" to unblock Machine* resources.

[CecileRobertMichon]

@devigned do you want to take this one? ( / does #691 fix it?)

[devigned]

Yep. I'll take this one.
/assign

[CecileRobertMichon]

seeing

E0810 21:15:19.487406       1 machinepool_controller.go:199] controllers/MachinePool "msg"="Reconciliation for MachinePool asked to requeue" "error"="Bootstrap provider for MachinePool \"machinepool-template-mp-0\" in namespace \"default\" is not ready, requeuing: requeue in 30s" "cluster"="machinepool-template" "machinepool"="machinepool-template-mp-0" "namespace"="default"
E0810 21:15:49.491280       1 machinepool_controller.go:199] controllers/MachinePool "msg"="Reconciliation for MachinePool asked to requeue" "error"="Bootstrap provider for MachinePool \"machinepool-template-mp-0\" in namespace \"default\" is not ready, requeuing: requeue in 30s" "cluster"="machinepool-template" "machinepool"="machinepool-template-mp-0" "namespace"="default"
E0810 21:16:19.495292       1 machinepool_controller.go:199] controllers/MachinePool "msg"="Reconciliation for MachinePool asked to requeue" "error"="Bootstrap provider for MachinePool \"machinepool-template-mp-0\" in namespace \"default\" is not ready, requeuing: requeue in 30s" "cluster"="machinepool-template" "machinepool"="machinepool-template-mp-0" "namespace"="default"
E0810 21:16:49.498704       1 machinepool_controller.go:199] controllers/MachinePool "msg"="Reconciliation for MachinePool asked to requeue" "error"="Bootstrap provider for MachinePool \"machinepool-template-mp-0\" in namespace \"default\" is not ready, requeuing: requeue in 30s" "cluster"="machinepool-template" "machinepool"="machinepool-template-mp-0" "namespace"="default"
E0810 21:17:19.503139       1 machinepool_controller.go:199] controllers/MachinePool "msg"="Reconciliation for MachinePool asked to requeue" "error"="Bootstrap provider for MachinePool \"machinepool-template-mp-0\" in namespace \"default\" is not ready, requeuing: requeue in 30s" "cluster"="machinepool-template" "machinepool"="machinepool-template-mp-0" "namespace"="default"
E0810 21:17:49.515326       1 machinepool_controller.go:199] controllers/MachinePool "msg"="Reconciliation for MachinePool asked to requeue" "error"="Bootstrap provider for MachinePool \"machinepool-template-mp-0\" in namespace \"default\" is not ready, requeuing: requeue in 30s" "cluster"="machinepool-template" "machinepool"="machinepool-template-mp-0" "namespace"="default"
E0810 21:18:19.518929       1 machinepool_controller.go:199] controllers/MachinePool "msg"="Reconciliation for MachinePool asked to requeue" "error"="Bootstrap provider for MachinePool \"machinepool-template-mp-0\" in namespace \"default\" is not ready, requeuing: requeue in 30s" "cluster"="machinepool-template" "machinepool"="machinepool-template-mp-0" "namespace"="default"

in CAPI logs

MachinePool is pending:

NAME                        REPLICAS   PHASE
machinepool-template-mp-0              Pending

[CecileRobertMichon]

Looking at the kubeadmconfig:

Status:
  Conditions:
    Last Transition Time:  2020-08-10T21:04:19Z
    Message:               0 of 2 completed
    Reason:                WaitingForClusterInfrastructure
    Severity:              Info
    Status:                False
    Type:                  Ready
    Last Transition Time:  2020-08-10T21:04:19Z
    Reason:                WaitingForClusterInfrastructure
    Severity:              Info
    Status:                False
    Type:                  DataSecretAvailable
  Observed Generation:     1
Events:                    <none>

kubectl get cluster 
NAME                   PHASE
machinepool-template   Provisioned

kubectl get azurecluster
NAME                   CLUSTER                READY
machinepool-template   machinepool-template   true

[CecileRobertMichon]

@devigned sorry I sort of stole this from you, I learned a lot about watches and predicates in the process though so not sorry 🙂

https://github.com/kubernetes-sigs/cluster-api/pull/3472 should fix it

[devigned]

Thank you, @CecileRobertMichon. I hadn't made much progress on it.