Occasional flake with OSProvisioningClientError

[jsturtevant]

We are seeing an occasional vm provisioning error:

"{\"status\":\"Failed\",\"error\":{\"code\":\"ResourceOperationFailure\",\"message\":\"The resource operation completed
 with terminal provisioning state 'Failed'.\",\"details\":[{\"code\":\"OSProvisioningClientError\",\"message\":\"OS 
Provisioning for VM 'capz-conf-6l2q7' did not finish in the allotted time. However, the VM guest agent was detected 
running. This suggests the guest OS has not been properly prepared to be used as a VM image (with 
CreateOption=FromImage). To resolve this issue, either use the VHD as is with CreateOption=Attach or prepare it 
properly for use as an image:\\r\\n * Instructions for Windows: https://learn.microsoft.com/azure/virtual-machines/windows/prepare-for-upload-vhd-image\\r\\n * Instructions for Linux: 
https://learn.microsoft.com/azure/virtual-machines/linux/create-upload-generic \"}]}}",

Interestingly the other node (which uses the same VHD image) came up just fine:

capz-conf-ry2zwl-control-plane-kpfmh   Ready    control-plane   3h48m   v1.33.0-beta.0.679+5c7491bf0874a8   10.0.0.4      <none>        Ubuntu 24.04.2 LTS               6.8.0-1021-azure   containerd://1.7.20
capz-conf-ss4bz                        Ready    <none>          3h45m   v1.33.0-beta.0.679+5c7491bf0874a8   10.1.0.5      <none>    

https://storage.googleapis.com/kubernetes-ci-logs/logs/ci-kubernetes-e2e-capz-master-windows/1905560033546997760/build-log.txt

We didn't get logs from the successful nodes since the logging code had a panic:

Done cleaning up after docker in docker.
Collecting logs for cluster capz-conf-ry2zwl in namespace default and dumping logs to /logs/artifacts
E0328 14:08:11.184919   42840 reflector.go:158] "Unhandled Error" err="pkg/mod/k8s.io/client-go@v0.31.3/tools/cache/reflector.go:243: Failed to watch *v1.Pod: Get \"https://capz-conf--capz-conf-ry2zwl-46678f-2uf8mw3o.hcp.northeurope.azmk8s.io:443/api/v1/pods?resourceVersion=91160&timeoutSeconds=438&watch=true\": dial tcp: lookup capz-conf--capz-conf-ry2zwl-46678f-2uf8mw3o.hcp.northeurope.azmk8s.io on 172.20.0.10:53: no such host" logger="UnhandledError"

the cluster name looks suspicious: capz-conf--capz-conf-ry2zwl-46678f-2uf8mw3o

[jsturtevant]

/cc @marosset @zylxjtu @iankingori

[jsturtevant]

One thing I've seen in the past is that if one of the pods crashes (say the calico pod) during the vm start up, i've seen the whole node fail. I haven't witnessed this in CI but saw it while I was working on #494. So maybe something is failing and taking down the bootstrap process?

[jsturtevant]

We create the cluster and wait for the Linux VM to start up but then once it is ready we deploy the workload configuration, At this time the windows node is startup up and gets the workload running before startup (cloud init) is complete.

Maybe if we wait for the windows VMs to report running and complete, then deploy configuration we would have higher success rate. The guess being that there is a race condition as to when kubelet reports the node online (which happens before the node reports ready in azure) and so api server gives it stuff to do. Some things are fully finished setting up and so there is something that goes wrong (as a race which is why it doesn't happen everytime) and the boot strap ends up failing.

[jsturtevant]

the release note here: could be similar to what I am suggesting: projectcalico/calico#8462

Added retry mechanism to Windows version retrieval in install-cni to address possible panics when the OS is not ready.

[jsturtevant]

I found further evidence this could be the case: https://github.com/jsturtevant/cluster-api-provider-azure/blob/f85555280f63f2f39dcde5e6deee80065f0b30c7/scripts/ci-entrypoint.sh#L211-L213

kubernetes-sigs/cluster-api-provider-azure#3148

[jsturtevant]

over the weekend we had one instance of this https://prow.k8s.io/view/gs/kubernetes-ci-logs/logs/ci-kubernetes-e2e-capz-master-windows/1906160244170428416.

Same error message in the azure portal as above This suggests the guest OS has not been properly prepared to be used as a VM image

[jsturtevant]

Waiting for the nodes to become "ready" in #497 did not work. We did capture the bug in its state and have determined that the cloud-init custom data is not being processed by cloudbase-init on the node that be reviewing the cloudbase-init logs.

failed logs:

2025-04-02 18:19:28.291 8 INFO cloudbaseinit.utils.windows.storage.vds_storage_manager [-] Extending volume "\\?\GLOBALROOT\Device\HarddiskVolume2" with 105225650176 bytes
2025-04-02 18:19:28.416 8 INFO cloudbaseinit.init [-] Executing plugin 'UserDataPlugin'
2025-04-02 18:19:28.432 8 INFO cloudbaseinit.init [-] Executing plugin 'EphemeralDiskPlugin'

successful:

2025-04-02 19:14:35.891 4428 INFO cloudbaseinit.init [-] Executing plugin 'UserDataPlugin'
2025-04-02 19:14:35.891 4428 DEBUG cloudbaseinit.plugins.common.userdata [-] User data content length: 9123 execute

There seem to be a couple possibilities:

• azure isn't always attaching the customdata in a place the cloudbase-init can find. Or there is some thing else going on during that interaction.
• Capz isn't reading/passing the bootstrap data properly. There is a caching function in capz. As well a place where it read the data from the secret. Its possible either of those is reading blank data.