Azure AKS cluster autoscaler hangs during up scaling

[netiperher]

CloudProvider: Azure AKS
Kubernetes version: 1.11.5
Cluster Autoscaler version: 1.3.5
ACS-Engine version: v0.26.3-aks

In our setup we run an Azure AKS cluster with multiple nodes that each run a single pod requiring all resources on the node. The pods are part of a statefulset that we scale quite aggressively from 2 to 20 and then back to 2 replicas at regular intervals.

Sometimes (<10%) when scaling up nodes the whole process takes considerable longer time than usual and this is often associated with the autoscaler pod crashing. When everything works normally the average time for us is 21 minutes when going from 2 to 20 nodes and when not working scaling up can take as long as 75 minutes.

Attached logs and screenshot of the cluster_autoscaler_nodes_count metric for when the upscaling stopped working after scaling up to 16 nodes and then nothing happens for 30 minutes.

Logs before crash (16:30 to 17:15)
autoscaler-azure-cluster-autoscaler-7c8df96664-h8fs4-before.log

Logs after crash (17:15 to 17:45)
autoscaler-azure-cluster-autoscaler-7c8df96664-h8fs4-after.log

Relevant log lines are around this lines

E0207 16:49:23.319809       1 static_autoscaler.go:283] Failed to scale up: failed to increase node group size: Code="" Message=""

cc @feiskyer

[feiskyer]

@netiperher Thanks for reporting the issue.

Sometimes (<10%) when scaling up nodes the whole process takes considerable longer time than usual and this is often associated with the autoscaler pod crashing.

Have you noticed why autoscaler pod is crashing? e.g. what errors are reporting then?

[netiperher]

When this happens (also in this example) the autoscaler is killed by the liveness probe. We use the default values of 3 failed probe at 10 second interval.

[aleksandra-malinowska]

Health check endpoint is updated at the end of every iteration. Probe will fail under two conditions: 1) if it hasn't been updated in 10 minutes (configured with --max-inactivity), or 2) if there was no successful run in 15 minutes (configured with --max-failing-time).

You can look for logs lines like these to check how long the iteration is taking (only logged if it's >5 seconds):

I0207 16:49:23.340692 1 metrics.go:267] Function main took 1m58.972537577s to complete

And lines like that to see when the iteration starts:

I0207 17:04:43.148590 1 static_autoscaler.go:131] Starting main loop

Based on the first log file, autoscaler was waiting for VM to be deleted for over 10 minutes:

I0207 17:04:43.554468       1 azure_util.go:150] deleting VM: MC_saas-aks_saas-aks_westeurope/aks-nodepool1-16716784-19
I0207 17:04:43.554473       1 azure_util.go:154] waiting for VirtualMachine deletion: MC_saas-aks_saas-aks_westeurope/aks-nodepool1-16716784-19
<nothing but waiting>
I0207 17:15:08.882168       1 main.go:247] Received signal, attempting cleanup
I0207 17:15:08.894553       1 main.go:249] Cleaned up, exiting...

My guess it that there's a missing timeout somewhere, but if this is expected time to delete a machine in some cases and you want to wait for it, consider adjusting --max-inactivity flag.

[netiperher]

So maybe there are two problems in this issue. One is that the autoscaler was killed, possibly due to deleting the VM took longer than normal.
The other issue that is also more relevant for us is why the autoscaler was stalled for 25 minutes between ~16:50 and 17:15. Somehow it failed during scale up from 16 to 20 nodes. But then after 15 minutes the machines are finally up, but then the autoscaler tries to remove them.

I0207 16:47:24.785972       1 scale_up.go:466] Final scale-up plan: [{nodepool1 16->20 (max: 20)}]
E0207 16:49:23.319809       1 static_autoscaler.go:283] Failed to scale up: failed to increase node group size: Code="" Message=""
I0207 16:49:33.647785       1 scale_up.go:291] Upcoming 4 nodes
I0207 16:49:54.595614       1 static_autoscaler.go:160] 4 unregistered nodes present
...
I0207 17:04:43.328124       1 utils.go:377] Removing unregistered node 
azure:///subscriptions/03388b22-6519-4128-939d-c24e9890b048/resourceGroups/MC_saas-aks_saas-aks_westeurope/providers/Microsoft.Compute/virtualMachines/aks-nodepool1-16716784-19

So one question is why the scale up failed? There is no error message to understand why this happens. Then why are the nodes removed when they are finally up?

[feiskyer]

There's something wrong in error message handling, just filed a PR #1703 to fix it.

[feiskyer]

@netiperher When digging the root causes, the error message of Code="" Message="" is actually because CA is using old Azure SDK versions. While it would need sometime for picking new changes, could you check the errors from Azure portal (e.g. from activity log)?

[netiperher]

@feiskyer thanks for the update, I'll check in the Azure portal the next time it happens (it has been 7 days now since the last time). If you have a new version with improved logging I'm willing to test that as well.

[feiskyer]

@netiperher sure, but it's not easy because the dependent packages (in new version) are actually conflicting with current packages in vendor (in old version). Would need to verify whether it works with overriding vendors for each CA releases.

[netiperher]

@feiskyer can you re-open this until we found the issue?
Do you have any plans to backport #1703 to 1.3 branch? Otherwise we'll just check for errors in the Azure portal as you recommended.

[feiskyer]

Yep, this should be kept open until cherry-picked.

/reopen

[k8s-ci-robot]

@feiskyer: Reopened this issue.

In response to this:

Yep, this should be kept open until cherry-picked.

/reopen

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.