This message was deleted.

Any errors in the vcenter UI when this happens?

Nope. Not the slightest hint in the UI. All looks normal besides the VM will not get started. I’m still waiting for the Ops Team to get logs from the vcenter or the ESXis.

If you could also grab the Rancher logs that would help - https://rancher.com/docs/rancher/v2.6/en/troubleshooting/logging/

Yes, I did.

rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:28:56 [INFO] [mgmt-cluster-rbac-delete] Creating namespace c-hfpq5
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:28:56 [INFO] [mgmt-cluster-rbac-delete] Creating Default project for cluster c-hfpq5
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:28:57 [INFO] [mgmt-project-rbac-create] Creating namespace p-kss8v
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:28:57 [INFO] [mgmt-cluster-rbac-delete] Creating System project for cluster c-hfpq5
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:28:57 [INFO] [mgmt-project-rbac-create] Creating creator projectRoleTemplateBinding for user user-b8srq for project p-kss8v
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:28:57 [INFO] [mgmt-auth-crtb-controller] Setting InitialRolesPopulated condition on project p-kss8v
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:28:57 [INFO] [mgmt-project-rbac-create] Creating namespace p-k4wp4
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:28:57 [INFO] [mgmt-cluster-rbac-delete] Updating cluster c-hfpq5
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:28:57 [INFO] [mgmt-auth-prtb-controller] Creating role/clusterRole p-kss8v-projectowner
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:28:57 [INFO] [mgmt-project-rbac-create] Creating creator projectRoleTemplateBinding for user user-b8srq for project p-k4wp4
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:28:57 [INFO] [mgmt-project-rbac-create] Updating project p-kss8v
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:28:57 [INFO] [mgmt-auth-prtb-controller] Creating roleBinding for membership in project p-kss8v for subject user-b8srq
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:28:57 [INFO] [mgmt-project-rbac-create] Updating project p-kss8v
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:28:57 [INFO] [mgmt-auth-prtb-controller] Creating role/clusterRole c-hfpq5-clustermember
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:28:57 [INFO] [mgmt-auth-crtb-controller] Setting InitialRolesPopulated condition on project p-k4wp4
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:28:57 [INFO] [mgmt-auth-prtb-controller] Creating role/clusterRole p-k4wp4-projectowner
rancher-6478674ddc-ccmjm rancher 2022/05/02 14:28:57 [WARNING] error updating ns c-hfpq5 status: Operation cannot be fulfilled on namespaces "c-hfpq5": the object has been modified; please apply your changes to the latest version and try again
rancher-6478674ddc-ccmjm rancher 2022/05/02 14:28:57 [WARNING] error updating ns p-kss8v status: Operation cannot be fulfilled on namespaces "p-kss8v": the object has been modified; please apply your changes to the latest version and try again
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:28:57 [INFO] [mgmt-auth-prtb-controller] Creating clusterRoleBinding for membership in cluster c-hfpq5 for subject user-b8srq
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:28:57 [INFO] [mgmt-project-rbac-create] Updating project p-k4wp4
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:28:57 [INFO] [mgmt-auth-prtb-controller] Creating roleBinding for membership in project p-k4wp4 for subject user-b8srq
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:28:57 [INFO] [mgmt-auth-prtb-controller] Creating role project-owner in namespace c-hfpq5
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:28:57 [INFO] [mgmt-auth-prtb-controller] Updating clusterRoleBinding clusterrolebinding-27btf for cluster membership in cluster c-hfpq5 for subject user-b8srq
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:28:57 [INFO] [mgmt-project-rbac-create] Updating project p-k4wp4
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:28:57 [INFO] [mgmt-auth-prtb-controller] Creating roleBinding for subject user-b8srq with role project-owner in namespace
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:28:57 [INFO] [mgmt-auth-prtb-controller] Creating role project-owner in namespace c-hfpq5
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:28:57 [INFO] [mgmt-cluster-rbac-delete] Updating cluster c-hfpq5
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:28:57 [INFO] [mgmt-auth-prtb-controller] Creating roleBinding for subject user-b8srq with role project-owner in namespace
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:28:57 [INFO] [mgmt-auth-prtb-controller] Creating role admin in namespace p-kss8v
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:28:57 [INFO] [mgmt-auth-prtb-controller] Creating role admin in namespace p-k4wp4
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:28:57 [INFO] [mgmt-project-rbac-create] Creating creator clusterRoleTemplateBinding for user user-b8srq for cluster c-hfpq5
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:28:57 [INFO] [mgmt-auth-prtb-controller] Creating role project-owner in namespace p-k4wp4
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:28:57 [INFO] [mgmt-auth-prtb-controller] Creating role project-owner in namespace p-kss8v
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:28:57 [INFO] [mgmt-auth-prtb-controller] Creating roleBinding for subject user-b8srq with role admin in namespace
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:28:57 [INFO] [mgmt-auth-prtb-controller] Creating roleBinding for subject user-b8srq with role admin in namespace
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:28:57 [INFO] [mgmt-auth-crtb-controller] Creating role/clusterRole c-hfpq5-clusterowner
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:28:57 [INFO] [mgmt-auth-prtb-controller] Creating roleBinding for subject user-b8srq with role project-owner in namespace
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:28:57 [INFO] [mgmt-auth-crtb-controller] Setting InitialRolesPopulated condition on cluster
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:28:57 [INFO] [mgmt-cluster-rbac-delete] Updating cluster c-hfpq5
rancher-6478674ddc-ccmjm rancher 2022/05/02 14:28:57 [WARNING] error updating ns p-k4wp4 status: Operation cannot be fulfilled on namespaces "p-k4wp4": the object has been modified; please apply your changes to the latest version and try again
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:28:57 [INFO] [mgmt-auth-crtb-controller] Creating clusterRoleBinding for membership in cluster c-hfpq5 for subject user-b8srq
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:28:57 [INFO] [mgmt-auth-prtb-controller] Creating roleBinding for subject user-b8srq with role project-owner in namespace
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:28:57 [INFO] [mgmt-auth-crtb-controller] Creating role cluster-owner in namespace c-hfpq5
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:28:57 [INFO] [mgmt-auth-crtb-controller] Creating roleBinding for subject user-b8srq with role cluster-owner in namespace
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:28:57 [INFO] [mgmt-auth-crtb-controller] Creating role cluster-owner in namespace p-kss8v
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:28:57 [INFO] [mgmt-auth-crtb-controller] Creating roleBinding for subject user-b8srq with role cluster-owner in namespace
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:28:57 [INFO] [mgmt-auth-crtb-controller] Creating role cluster-owner in namespace p-k4wp4
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:28:57 [INFO] [mgmt-auth-crtb-controller] Creating roleBinding for subject user-b8srq with role cluster-owner in namespace
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:28:57 [INFO] [mgmt-cluster-rbac-delete] Updating cluster c-hfpq5
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:28:59 [INFO] Creating jail for c-hfpq5
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:28:59 [INFO] Provisioning node vsnodes1
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:28:59 [INFO] [node-controller-rancher-machine] Creating CA: /management-state/node/nodes/vsnodes1/certs/ca.pem
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:28:59 [INFO] [node-controller-rancher-machine] Creating client certificate: /management-state/node/nodes/vsnodes1/certs/cert.pem
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:28:59 [INFO] [node-controller-rancher-machine] Running pre-create checks...
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:28:59 [INFO] [node-controller-rancher-machine] (vsnodes1) Connecting to vSphere for pre-create checks...
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:29:02 [INFO] [node-controller-rancher-machine] Creating machine...
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:29:02 [INFO] [node-controller-rancher-machine] (vsnodes1) Generating SSH Keypair...
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:29:04 [INFO] [node-controller-rancher-machine] (vsnodes1) Cloning VM from VM or Template: /myCompany/vm/System Team/K8S/Templates/k8sworkernodetemplate...
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:29:04 [INFO] [node-controller-rancher-machine] (vsnodes1) Finding datastore /myCompany/datastore/vsanprod
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:29:16 [INFO] [node-controller-rancher-machine] (vsnodes1) Adding network: /myCompany/network/vDPG-Clientnetz-VLAN172
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:29:17 [INFO] [node-controller-rancher-machine] (vsnodes1) Resizing disk disk-1000-0 up from 102400000Kb to 256000000Kb
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:29:17 [INFO] [node-controller-rancher-machine] (vsnodes1) Setting disk.enableUUID to TRUE
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:29:17 [INFO] [node-controller-rancher-machine] (vsnodes1) Creating cloud-init.iso
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:29:17 [INFO] [node-controller-rancher-machine] (vsnodes1) Uploading cloud-init.iso
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:29:19 [INFO] [node-controller-rancher-machine] The default lines below are for a sh/bash shell, you can specify the shell you're using, with the --shell flag.
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:29:19 [INFO] [node-controller-rancher-machine]
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:29:23 [INFO] Generating and uploading node config vsnodes1
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:29:23 [ERROR] [node] enqueing node pool c-hfpq5:np-8mcbp
rancher-6478674ddc-p6lr4 rancher 2022/05/02 14:29:23 [ERROR] error syncing 'c-hfpq5/m-n9mdk': handler node-controller: Error creating machine: Error in driver during machine creation: 500 Internal Server Error, requeuing

Might want to bump that to trace level but it will include sensitive data

Are you using node templates? I’ve seen this issue when there is something not set right in there. And vSphere doesn’t know how to interpret it, and the API sends back that 500. I’ve also seen this issue when something is not right with the cloud-init format.

Yes, we’re using node templates. Funny thing is, that vcenter says, that the fileupload of the user-data.iso has been succesfully initiated but the file is not there where it supposed to be, it’s missing. And this is exactly the point where the cluster provisioning fails.

Watch it and see if it briefly pops in, when the process fails that file may get deleted and then uploaded again on a retry.

This is the part from the trace where it fails:

rancher-6478674ddc-p6lr4 rancher 2022/05/02 16:06:49 [TRACE] REST UPDATE apis/management.cattle.io/v3/c-cpgpw/nodes/m-gqzsm
rancher-6478674ddc-p6lr4 rancher 2022/05/02 16:06:49 [TRACE] [node-controller-rancher-machine] (vsnodes1) DBG | </soapenv:Body>
rancher-6478674ddc-p6lr4 rancher 2022/05/02 16:06:49 [TRACE] REST UPDATE apis/management.cattle.io/v3/c-cpgpw/nodes/m-gqzsm
rancher-6478674ddc-p6lr4 rancher 2022/05/02 16:06:49 [TRACE] [node-controller-rancher-machine] (vsnodes1) DBG | </s
rancher-6478674ddc-p6lr4 rancher 2022/05/02 16:06:49 [TRACE] REST UPDATE apis/management.cattle.io/v3/c-cpgpw/nodes/m-gqzsm
rancher-6478674ddc-p6lr4 rancher 2022/05/02 16:06:49 [TRACE] [node-controller-rancher-machine] (vsnodes1) DBG | 2022/05/02 16:06:48 oapenv:Envelope>
rancher-6478674ddc-p6lr4 rancher 2022/05/02 16:06:49 [TRACE] REST UPDATE apis/management.cattle.io/v3/c-cpgpw/nodes/m-gqzsm
rancher-6478674ddc-ccmjm rancher 2022/05/02 16:06:50 [TRACE] EndpointsController calling handler dnsRecordEndpointsController kube-system/kube-controller-manager
rancher-6478674ddc-p6lr4 rancher 2022/05/02 16:06:50 [INFO] [node-controller-rancher-machine] The default lines below are for a sh/bash shell, you can specify the shell you're using, with the --shell flag.
rancher-6478674ddc-p6lr4 rancher 2022/05/02 16:06:50 [TRACE] REST UPDATE apis/management.cattle.io/v3/c-cpgpw/nodes/m-gqzsm
rancher-6478674ddc-p6lr4 rancher 2022/05/02 16:06:50 [INFO] [node-controller-rancher-machine]
rancher-6478674ddc-p6lr4 rancher 2022/05/02 16:06:50 [TRACE] REST UPDATE apis/management.cattle.io/v3/c-cpgpw/nodes/m-gqzsm
rancher-6478674ddc-ccmjm rancher 2022/05/02 16:06:50 [TRACE] EndpointsController calling handler dnsRecordEndpointsController kube-system/kube-scheduler
rancher-6478674ddc-dmxgm rancher 2022/05/02 16:06:51 [TRACE] machineName: returning [m-221393135bcf] for node with RequestedHostname [worker4]
rancher-6478674ddc-dmxgm rancher 2022/05/02 16:06:51 [TRACE] getMachine: looking up machine [m-221393135bcf] in cluster [c-cvr8q]
rancher-6478674ddc-p6lr4 rancher 2022/05/02 16:06:51 [DEBUG] Wrote ping
rancher-6478674ddc-p6lr4 rancher 2022/05/02 16:06:51 [DEBUG] closing watcher for management.cattle.io.project
rancher-6478674ddc-p6lr4 rancher 2022/05/02 16:06:51 [INFO] Generating and uploading node config vsnodes1
rancher-6478674ddc-p6lr4 rancher 2022/05/02 16:06:51 [DEBUG] getNodeTemplate parsed [cattle-global-nt:nt-pk2bj] to ns: [cattle-global-nt] and n: [nt-pk2bj]
rancher-6478674ddc-p6lr4 rancher 2022/05/02 16:06:51 [TRACE] REST GET apis/management.cattle.io/v3/cattle-global-nt/nodetemplates/nt-pk2bj
rancher-6478674ddc-p6lr4 rancher 2022/05/02 16:06:51 [ERROR] [node] enqueing node pool c-cpgpw:np-ljgzv
rancher-6478674ddc-p6lr4 rancher 2022/05/02 16:06:51 [DEBUG] Cleaning up [/opt/jail/c-cpgpw/management-state/node/nodes/vsnodes1]
rancher-6478674ddc-p6lr4 rancher 2022/05/02 16:06:51 [TRACE] REST UPDATE apis/management.cattle.io/v3/c-cpgpw/nodes/m-gqzsm
rancher-6478674ddc-p6lr4 rancher 2022/05/02 16:06:51 [TRACE] NodePoolController calling handler nodepool-provisioner c-cpgpw/np-ljgzv
rancher-6478674ddc-p6lr4 rancher 2022/05/02 16:06:51 [TRACE] REST LIST apis/management.cattle.io/v3/c-cpgpw/nodes
rancher-6478674ddc-p6lr4 rancher 2022/05/02 16:06:51 [TRACE] NodeController calling handler node-controller-sync c-cpgpw/m-gqzsm
rancher-6478674ddc-p6lr4 rancher 2022/05/02 16:06:51 [TRACE] REST UPDATE apis/management.cattle.io/v3/c-cpgpw/nodes/m-gqzsm
rancher-6478674ddc-p6lr4 rancher 2022/05/02 16:06:51 [TRACE] NodeController calling handler rke-worker-upgrader c-cpgpw/m-gqzsm
rancher-6478674ddc-p6lr4 rancher 2022/05/02 16:06:51 [ERROR] error syncing 'c-cpgpw/m-gqzsm': handler node-controller: notifying bugsnag: [Error creating machine: Error in driver during machine creation: 500 Internal Server Error], requeuing

I don’t have one sadly.

Hi. It turned out that this issue is an permission problem. We used the rancher documetation to create the vSphere user that is used by the cloud credentials and we ran into this error. I tried now tried the vSphere internal admin account and it worked. Something strange is going on in our vSphere permission settings. I just wanted to let you guys know. Thank you very much.

That’s great to hear, thanks for the follow-up. How very odd the logs were not indicative of that at all…

Yes you’re absolutely right. All I get is this 500 Error. Very hard to debug.