jingxu97
commented
1 year ago We hit similar bugs with vSphere csi driver 3.0. More details as follows.
Starting from 3.0, cns topology feature flag is removed, and cannot be turned off OSS change. By comparing the passed log and failed logs, looks like there might be race condition happened during node registration. And the logic does not has a retry so the the following logic depending on it will fail.
vsphere-csi-node-mbdjf 1/2 CrashLoopBackOff Node driver registry log
2023-03-31T12:28:22.245291043Z I0331 12:28:22.245133 1 main.go:102] Received GetInfo call: &InfoRequest{}
2023-03-31T12:28:22.245783165Z I0331 12:28:22.245690 1 main.go:109] "Kubelet registration probe created" path="/var/lib/kubelet/plugins/csi.vsphere.vmware.com/registration"
2023-03-31T12:29:22.269924126Z I0331 12:29:22.269721 1 main.go:121] Received NotifyRegistrationStatus call: &RegistrationStatus{PluginRegistered:false,Error:RegisterPlugin error -- plugin registration failed with err: rpc error: code = Internal desc = timed out while waiting for topology labels to be updated in "c01057a88824-qual-323-0afbb584" CSINodeTopology instance.,}
2023-03-31T12:29:22.269969201Z E0331 12:29:22.269834 1 main.go:123] Registration process failed with error: RegisterPlugin error -- plugin registration failed with err: rpc error: code = Internal desc = timed out while waiting for topology labels to be updated in "c01057a88824-qual-323-0afbb584" CSINodeTopology instance., restarting registration container.vsphere-csi-driver log
2023-03-31T11:33:28.319787659Z {"level":"info","time":"2023-03-31T11:33:28.319728628Z","caller":"kubernetes/kubernetes.go:395","msg":"Setting client QPS to 100.000000 and Burst to 100.","TraceId":"a7e5dbf2-7c1d-4fb3-9fb3-730e47f69001"}
2023-03-31T11:33:28.345686928Z {"level":"info","time":"2023-03-31T11:33:28.344293416Z","caller":"k8sorchestrator/topology.go:727","msg":"Topology service initiated successfully","TraceId":"a7e5dbf2-7c1d-4fb3-9fb3-730e47f69001"}
2023-03-31T11:33:28.372612710Z {"level":"info","time":"2023-03-31T11:33:28.37245886Z","caller":"k8sorchestrator/topology.go:895","msg":"Successfully created a CSINodeTopology instance for NodeName: \"c01057a88824-qual-323-0afbb584\"","TraceId":"a7e5dbf2-7c1d-4fb3-9fb3-730e47f69001"}
2023-03-31T11:34:28.375379515Z {"level":"error","time":"2023-03-31T11:34:28.374319044Z","caller":"k8sorchestrator/topology.go:837","msg":"timed out while waiting for topology labels to be updated in \"c01057a88824-qual-323-0afbb584\" CSINodeTopology instance.","TraceId":"a7e5dbf2-7c1d-4fb3-9fb3-730e47f69001","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/common/commonco/k8sorchestrator.(*nodeVolumeTopology).GetNodeTopologyLabels\n\t/build/pkg/csi/service/common/commonco/k8sorchestrator/topology.go:837\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service.(*vsphereCSIDriver).NodeGetInfo\n\t/build/pkg/csi/service/node.go:429\ngithub.com/container-storage-interface/spec/lib/go/csi._Node_NodeGetInfo_Handler\n\t/go/pkg/mod/github.com/container-storage-interface/spec@v1.7.0/lib/go/csi/csi.pb.go:6231\ngoogle.golang.org/grpc.(*Server).processUnaryRPC\n\t/go/pkg/mod/google.golang.org/grpc@v1.47.0/server.go:1283\ngoogle.golang.org/grpc.(*Server).handleStream\n\t/go/pkg/mod/google.golang.org/grpc@v1.47.0/server.go:1620\ngoogle.golang.org/grpc.(*Server).serveStreams.func1.2\n\t/go/pkg/mod/google.golang.org/grpc@v1.47.0/server.go:922"}
2023-03-31T11:34:30.358756419Z {"level":"info","time":"2023-03-31T11:34:30.358584895Z","caller":"service/node.go:338","msg":"NodeGetInfo: called with args {XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}","TraceId":"f21e5f14-20bf-4bb0-a70b-2322ee91fa34"}
2023-03-31T11:34:30.372726452Z {"level":"info","time":"2023-03-31T11:34:30.37258219Z","caller":"k8sorchestrator/topology.go:892","msg":"CSINodeTopology instance already exists for NodeName: \"c01057a88824-qual-323-0afbb584\"","TraceId":"f21e5f14-20bf-4bb0-a70b-2322ee91fa34"}
2023-03-31T11:35:30.375537038Z {"level":"error","time":"2023-03-31T11:35:30.374942664Z","caller":"k8sorchestrator/topology.go:837","msg":"timed out while waiting for topology labels to be updated in \"c01057a88824-qual-323-0afbb584\" CSINodeTopology instance.","TraceId":"f21e5f14-20bf-4bb0-a70b-2322ee91fa34","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/common/commonco/k8sorchestrator.(*nodeVolumeTopology).GetNodeTopologyLabels\n\t/build/pkg/csi/service/common/commonco/k8sorchestrator/topology.go:837\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service.(*vsphereCSIDriver).NodeGetInfo\n\t/build/pkg/csi/service/node.go:429\ngithub.com/container-storage-interface/spec/lib/go/csi._Node_NodeGetInfo_Handler\n\t/go/pkg/mod/github.com/container-storage-interface/spec@v1.7.0/lib/go/csi/csi.pb.go:6231\ngoogle.golang.org/grpc.(*Server).processUnaryRPC\n\t/go/pkg/mod/google.golang.org/grpc@v1.47.0/server.go:1283\ngoogle.golang.org/grpc.(*Server).handleStream\n\t/go/pkg/mod/google.golang.org/grpc@v1.47.0/server.go:1620\ngoogle.golang.org/grpc.(*Server).serveStreams.func1.2\n\t/go/pkg/mod/google.golang.org/grpc@v1.47.0/server.go:922"}
"kubectl_logs_vsphere-csi-node-mbdjf_--container_vsphere-csi-node_--kubeconfig_.tmp.user-kubeconfig-56089268_--request-timeout_30s_--namespace_kube-system_--timestamps" 63L, 29225BSome logs from vsphere-csi-controller:
- Passed test Passing log: Notice that "Successfully registered VC mtv-qual-vc03.anthos:443" happened first. All the following node/VM can be found
2023-03-30T03:27:10.857292378Z {"level":"info","time":"2023-03-30T03:27:10.857253925Z","caller":"vsphere/virtualcentermanager.go:123","msg":"Successfully registered VC mtv-qual-vc03.anthos:443"}
2023-03-30T03:27:10.857373990Z {"level":"info","time":"2023-03-30T03:27:10.857306174Z","caller":"vsphere/virtualcenter.go:283","msg":"VirtualCenter.connect() creating new client"}
2023-03-30T03:27:10.860343329Z {"level":"info","time":"2023-03-30T03:27:10.860255209Z","caller":"node/manager.go:128","msg":"Discovering the node vm using uuid: \"4211ec99-cb15-a5cd-3193-49bb2883a3fb\"","TraceId":"a360dbae-71de-43a2-8b2b-38fff67feebb"}
2023-03-30T03:27:10.860354679Z {"level":"info","time":"2023-03-30T03:27:10.860281279Z","caller":"vsphere/virtualmachine.go:159","msg":"Initiating asynchronous datacenter listing with uuid 4211ec99-cb15-a5cd-3193-49bb2883a3fb","TraceId":"a360dbae-71de-43a2-8b2b-38fff67feebb"}
2023-03-30T03:27:10.883477322Z {"level":"info","time":"2023-03-30T03:27:10.883355912Z","caller":"k8sorchestrator/k8sorchestrator.go:644","msg":"configMapAdded: Internal feature state values from \"internal-feature-states.csi.vsphere.vmware.com\" stored successfully: map[async-query-volume:true block-volume-snapshot:true csi-migration:true csi-windows-support:true improved-csi-idempotency:true online-volume-extend:true trigger-csi-fullsync:false]","TraceId":"bd419e1b-0881-4e2e-b9d4-b90f744c9a1b"}
2023-03-30T03:27:10.914441786Z {"level":"info","time":"2023-03-30T03:27:10.914259728Z","caller":"vsphere/virtualcenter.go:202","msg":"New session ID for 'VSPHERE.LOCAL\\herc-32210b8fe0bd' = 52611e95-9457-8d31-c11e-9edbca63b82e"}
2023-03-30T03:27:10.914464578Z {"level":"info","time":"2023-03-30T03:27:10.914314422Z","caller":"vsphere/virtualcenter.go:291","msg":"VirtualCenter.connect() successfully created new client"}
2023-03-30T03:27:10.914468743Z {"level":"info","time":"2023-03-30T03:27:10.914338151Z","caller":"vsphere/virtualcenter.go:606","msg":"vCenterInstance initialized"}
2023-03-30T03:27:10.914549752Z {"level":"info","time":"2023-03-30T03:27:10.914476906Z","caller":"volume/manager.go:193","msg":"Initializing new defaultManager..."}
2023-03-30T03:27:10.914677990Z {"level":"info","time":"2023-03-30T03:27:10.914582011Z","caller":"syncer/metadatasyncer.go:417","msg":"Adding watch on path: \"/etc/cloud\""}
2023-03-30T03:27:10.914813271Z {"level":"info","time":"2023-03-30T03:27:10.914732425Z","caller":"volume/manager.go:190","msg":"Retrieving existing defaultManager..."}
2023-03-30T03:27:10.917155580Z {"level":"info","time":"2023-03-30T03:27:10.917045953Z","caller":"kubernetes/kubernetes.go:79","msg":"k8s client using kubeconfig from /etc/kubernetes/kubeconfig.conf"}
2023-03-30T03:27:10.917932242Z {"level":"info","time":"2023-03-30T03:27:10.917828978Z","caller":"kubernetes/kubernetes.go:395","msg":"Setting client QPS to 100.000000 and Burst to 100."}
2023-03-30T03:27:10.924330377Z {"level":"info","time":"2023-03-30T03:27:10.924234917Z","caller":"vsphere/datacenter.go:154","msg":"Publishing datacenter Datacenter [Datacenter: Datacenter:datacenter-2 @ /mtv-qual-vc03, VirtualCenterHost: mtv-qual-vc03.anthos]","TraceId":"a360dbae-71de-43a2-8b2b-38fff67feebb"}
2023-03-30T03:27:10.924393747Z {"level":"info","time":"2023-03-30T03:27:10.924310978Z","caller":"vsphere/virtualmachine.go:196","msg":"AsyncGetAllDatacenters with uuid 4211ec99-cb15-a5cd-3193-49bb2883a3fb sent a dc Datacenter [Datacenter: Datacenter:datacenter-2 @ /mtv-qual-vc03, VirtualCenterHost: mtv-qual-vc03.anthos]","TraceId":"a360dbae-71de-43a2-8b2b-38fff67feebb"}
2023-03-30T03:27:10.933106473Z {"level":"info","time":"2023-03-30T03:27:10.933012951Z","caller":"vsphere/virtualmachine.go:210","msg":"Found VM VirtualMachine:vm-623336 [VirtualCenterHost: mtv-qual-vc03.anthos, UUID: 4211ec99-cb15-a5cd-3193-49bb2883a3fb, Datacenter: Datacenter [Datacenter: Datacenter:datacenter-2 @ /mtv-qual-vc03, VirtualCenterHost: mtv-qual-vc03.anthos]] given uuid 4211ec99-cb15-a5cd-3193-49bb2883a3fb on DC Datacenter [Datacenter: Datacenter:datacenter-2 @ /mtv-qual-vc03, VirtualCenterHost: mtv-qual-vc03.anthos]","TraceId":"a360dbae-71de-43a2-8b2b-38fff67feebb"}
2023-03-30T03:27:10.933121137Z {"level":"info","time":"2023-03-30T03:27:10.93304699Z","caller":"vsphere/virtualmachine.go:221","msg":"Returning VM VirtualMachine:vm-623336 [VirtualCenterHost: mtv-qual-vc03.anthos, UUID: 4211ec99-cb15-a5cd-3193-49bb2883a3fb, Datacenter: Datacenter [Datacenter: Datacenter:datacenter-2 @ /mtv-qual-vc03, VirtualCenterHost: mtv-qual-vc03.anthos]] for UUID 4211ec99-cb15-a5cd-3193-49bb2883a3fb","TraceId":"a360dbae-71de-43a2-8b2b-38fff67feebb"}
2023-03-30T03:27:10.933125305Z {"level":"info","time":"2023-03-30T03:27:10.933063049Z","caller":"node/manager.go:151","msg":"Successfully discovered node with nodeUUID 4211ec99-cb15-a5cd-3193-49bb2883a3fb in vm VirtualMachine:vm-623336 [VirtualCenterHost: mtv-qual-vc03.anthos, UUID: 4211ec99-cb15-a5cd-3193-49bb2883a3fb, Datacenter: Datacenter [Datacenter: Datacenter:datacenter-2 @ /mtv-qual-vc03, VirtualCenterHost: mtv-qual-vc03.anthos]]","TraceId":"a360dbae-71de-43a2-8b2b-38fff67feebb"}
2023-03-30T03:27:10.933128956Z {"level":"info","time":"2023-03-30T03:27:10.933073905Z","caller":"node/manager.go:134","msg":"Successfully discovered node: \"32210b8fe0bd-qual-private306-15003d10\" with nodeUUID \"4211ec99-cb15-a5cd-3193-49bb2883a3fb\"","TraceId":"a360dbae-71de-43a2-8b2b-38fff67feebb"}
2023-03-30T03:27:10.933136796Z {"level":"info","time":"2023-03-30T03:27:10.933081969Z","caller":"node/manager.go:136","msg":"Successfully registered node: \"32210b8fe0bd-qual-private306-15003d10\" with nodeUUID \"4211ec99-cb15-a5cd-3193-49bb2883a3fb\"","TraceId":"a360dbae-71de-43a2-8b2b-38fff67feebb"- Failed test (More logs https://gist.github.com/jingxu97/cc013868270f4d05497a7aba2b59221c) Failed log: before VC is registered, there are "VM not found " error first. After VC is registered, the rest of the nodes can be found.
2023-03-31T11:33:19.880026310Z {"level":"info","time":"2023-03-31T11:33:19.691025909Z","caller":"vsphere/virtualcentermanager.go:74","msg":"Initializing defaultVirtualCenterManager..."}
2023-03-31T11:33:19.880028344Z {"level":"info","time":"2023-03-31T11:33:19.69104239Z","caller":"vsphere/virtualcentermanager.go:76","msg":"Successfully initialized defaultVirtualCenterManager"}
2023-03-31T11:33:19.880031590Z {"level":"error","time":"2023-03-31T11:33:19.691146997Z","caller":"vsphere/virtualmachine.go:227","msg":"Returning VM not found err for UUID 420efa50-4b8b-f108-347a-0a8f21fdb714","TraceId":"973eef74-6eac-4af0-abeb-5cd217b8eaa1","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v3/pkg/common/cns-lib/vsphere.GetVirtualMachineByUUID\n\t/build/pkg/common/cns-lib/vsphere/virtualmachine.go:227\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/common/cns-lib/node.(*defaultManager).DiscoverNode\n\t/build/pkg/common/cns-lib/node/manager.go:145\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/common/cns-lib/node.(*defaultManager).RegisterNode\n\t/build/pkg/common/cns-lib/node/manager.go:129\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/common/cns-lib/node.(*Nodes).nodeAdd\n\t/build/pkg/common/cns-lib/node/nodes.go:69\nk8s.io/client-go/tools/cache.ResourceEventHandlerFuncs.OnAdd\n\t/go/pkg/mod/k8s.io/client-go@v0.25.2/tools/cache/controller.go:232\nk8s.io/client-go/tools/cache.(*processorListener).run.func1\n\t/go/pkg/mod/k8s.io/client-go@v0.25.2/tools/cache/shared_informer.go:818\nk8s.io/apimachinery/pkg/util/wait.BackoffUntil.func1\n\t/go/pkg/mod/k8s.io/apimachinery@v0.25.2/pkg/util/wait/wait.go:157\nk8s.io/apimachinery/pkg/util/wait.BackoffUntil\n\t/go/pkg/mod/k8s.io/apimachinery@v0.25.2/pkg/util/wait/wait.go:158\nk8s.io/apimachinery/pkg/util/wait.JitterUntil\n\t/go/pkg/mod/k8s.io/apimachinery@v0.25.2/pkg/util/wait/wait.go:135\nk8s.io/apimachinery/pkg/util/wait.Until\n\t/go/pkg/mod/k8s.io/apimachinery@v0.25.2/pkg/util/wait/wait.go:92\nk8s.io/client-go/tools/cache.(*processorListener).run\n\t/go/pkg/mod/k8s.io/client-go@v0.25.2/tools/cache/shared_informer.go:812\nk8s.io/apimachinery/pkg/util/wait.(*Group).Start.func1\n\t/go/pkg/mod/k8s.io/apimachinery@v0.25.2/pkg/util/wait/wait.go:75"}
2023-03-31T11:33:19.880046207Z {"level":"error","time":"2023-03-31T11:33:19.691213382Z","caller":"node/manager.go:147","msg":"Couldn't find VM instance with nodeUUID 420efa50-4b8b-f108-347a-0a8f21fdb714, failed to discover with err: virtual machine wasn't found","TraceId":"973eef74-6eac-4af0-abeb-5cd217b8eaa1","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v3/pkg/common/cns-lib/node.(*defaultManager).DiscoverNode\n\t/build/pkg/common/cns-lib/node/manager.go:147\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/common/cns-lib/node.(*defaultManager).RegisterNode\n\t/build/pkg/common/cns-lib/node/manager.go:129\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/common/cns-lib/node.(*Nodes).nodeAdd\n\t/build/pkg/common/cns-lib/node/nodes.go:69\nk8s.io/client-go/tools/cache.ResourceEventHandlerFuncs.OnAdd\n\t/go/pkg/mod/k8s.io/client-go@v0.25.2/tools/cache/controller.go:232\nk8s.io/client-go/tools/cache.(*processorListener).run.func1\n\t/go/pkg/mod/k8s.io/client-go@v0.25.2/tools/cache/shared_informer.go:818\nk8s.io/apimachinery/pkg/util/wait.BackoffUntil.func1\n\t/go/pkg/mod/k8s.io/apimachinery@v0.25.2/pkg/util/wait/wait.go:157\nk8s.io/apimachinery/pkg/util/wait.BackoffUntil\n\t/go/pkg/mod/k8s.io/apimachinery@v0.25.2/pkg/util/wait/wait.go:158\nk8s.io/apimachinery/pkg/util/wait.JitterUntil\n\t/go/pkg/mod/k8s.io/apimachinery@v0.25.2/pkg/util/wait/wait.go:135\nk8s.io/apimachinery/pkg/util/wait.Until\n\t/go/pkg/mod/k8s.io/apimachinery@v0.25.2/pkg/util/wait/wait.go:92\nk8s.io/client-go/tools/cache.(*processorListener).run\n\t/go/pkg/mod/k8s.io/client-go@v0.25.2/tools/cache/shared_informer.go:812\nk8s.io/apimachinery/pkg/util/wait.(*Group).Start.func1\n\t/go/pkg/mod/k8s.io/apimachinery@v0.25.2/pkg/util/wait/wait.go:75"}
2023-03-31T11:33:19.880051146Z {"level":"error","time":"2023-03-31T11:33:19.691256924Z","caller":"node/manager.go:131","msg":"failed to discover VM with uuid: \"420efa50-4b8b-f108-347a-0a8f21fdb714\" for node: \"c01057a88824-qual-323-0afbb5d7\"","TraceId":"973eef74-6eac-4af0-abeb-5cd217b8eaa1","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v3/pkg/common/cns-lib/node.(*defaultManager).RegisterNode\n\t/build/pkg/common/cns-lib/node/manager.go:131\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/common/cns-lib/node.(*Nodes).nodeAdd\n\t/build/pkg/common/cns-lib/node/nodes.go:69\nk8s.io/client-go/tools/cache.ResourceEventHandlerFuncs.OnAdd\n\t/go/pkg/mod/k8s.io/client-go@v0.25.2/tools/cache/controller.go:232\nk8s.io/client-go/tools/cache.(*processorListener).run.func1\n\t/go/pkg/mod/k8s.io/client-go@v0.25.2/tools/cache/shared_informer.go:818\nk8s.io/apimachinery/pkg/util/wait.BackoffUntil.func1\n\t/go/pkg/mod/k8s.io/apimachinery@v0.25.2/pkg/util/wait/wait.go:157\nk8s.io/apimachinery/pkg/util/wait.BackoffUntil\n\t/go/pkg/mod/k8s.io/apimachinery@v0.25.2/pkg/util/wait/wait.go:158\nk8s.io/apimachinery/pkg/util/wait.JitterUntil\n\t/go/pkg/mod/k8s.io/apimachinery@v0.25.2/pkg/util/wait/wait.go:135\nk8s.io/apimachinery/pkg/util/wait.Until\n\t/go/pkg/mod/k8s.io/apimachinery@v0.25.2/pkg/util/wait/wait.go:92\nk8s.io/client-go/tools/cache.(*processorListener).run\n\t/go/pkg/mod/k8s.io/client-go@v0.25.2/tools/cache/shared_informer.go:812\nk8s.io/apimachinery/pkg/util/wait.(*Group).Start.func1\n\t/go/pkg/mod/k8s.io/apimachinery@v0.25.2/pkg/util/wait/wait.go:75"}
2023-03-31T11:33:19.880056226Z {"level":"warn","time":"2023-03-31T11:33:19.691282823Z","caller":"node/nodes.go:72","msg":"failed to register node:\"c01057a88824-qual-323-0afbb5d7\". err=virtual machine wasn't found","TraceId":"973eef74-6eac-4af0-abeb-5cd217b8eaa1"}
2023-03-31T11:33:19.880058280Z {"level":"info","time":"2023-03-31T11:33:19.691529217Z","caller":"node/manager.go:128","msg":"Discovering the node vm using uuid: \"420e47c7-ba23-d2a8-6656-526432f8313b\"","TraceId":"2ceea003-59f4-4aa9-a37c-b2af5e4c48be"}
2023-03-31T11:33:19.880060013Z {"level":"info","time":"2023-03-31T11:33:19.691588529Z","caller":"vsphere/virtualmachine.go:159","msg":"Initiating asynchronous datacenter listing with uuid 420e47c7-ba23-d2a8-6656-526432f8313b","TraceId":"2ceea003-59f4-4aa9-a37c-b2af5e4c48be"}
2023-03-31T11:33:19.880066836Z {"level":"error","time":"2023-03-31T11:33:19.691638263Z","caller":"vsphere/virtualmachine.go:227","msg":"Returning VM not found err for UUID 420e47c7-ba23-d2a8-6656-526432f8313b","TraceId":"2ceea003-59f4-4aa9-a37c-b2af5e4c48be","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v3/pkg/common/cns-lib/vsphere.GetVirtualMachineByUUID\n\t/build/pkg/common/cns-lib/vsphere/virtualmachine.go:227\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/common/cns-lib/node.(*defaultManager).DiscoverNode\n\t/build/pkg/common/cns-lib/node/manager.go:145\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/common/cns-lib/node.(*defaultManager).RegisterNode\n\t/build/pkg/common/cns-lib/node/manager.go:129\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/common/cns-lib/node.(*Nodes).nodeAdd\n\t/build/pkg/common/cns-lib/node/nodes.go:69\nk8s.io/client-go/tools/cache.ResourceEventHandlerFuncs.OnAdd\n\t/go/pkg/mod/k8s.io/client-go@v0.25.2/tools/cache/controller.go:232\nk8s.io/client-go/tools/cache.(*processorListener).run.func1\n\t/go/pkg/mod/k8s.io/client-go@v0.25.2/tools/cache/shared_informer.go:818\nk8s.io/apimachinery/pkg/util/wait.BackoffUntil.func1\n\t/go/pkg/mod/k8s.io/apimachinery@v0.25.2/pkg/util/wait/wait.go:157\nk8s.io/apimachinery/pkg/util/wait.BackoffUntil\n\t/go/pkg/mod/k8s.io/apimachinery@v0.25.2/pkg/util/wait/wait.go:158\nk8s.io/apimachinery/pkg/util/wait.JitterUntil\n\t/go/pkg/mod/k8s.io/apimachinery@v0.25.2/pkg/util/wait/wait.go:135\nk8s.io/apimachinery/pkg/util/wait.Until\n\t/go/pkg/mod/k8s.io/apimachinery@v0.25.2/pkg/util/wait/wait.go:92\nk8s.io/client-go/tools/cache.(*processorListener).run\n\t/go/pkg/mod/k8s.io/client-go@v0.25.2/tools/cache/shared_informer.go:812\nk8s.io/apimachinery/pkg/util/wait.(*Group).Start.func1\n\t/go/pkg/mod/k8s.io/apimachinery@v0.25.2/pkg/util/wait/wait.go:75"}
2023-03-31T11:33:19.880069351Z {"level":"error","time":"2023-03-31T11:33:19.691715308Z","caller":"node/manager.go:147","msg":"Couldn't find VM instance with nodeUUID 420e47c7-ba23-d2a8-6656-526432f8313b, failed to discover with err: virtual machine wasn't found","TraceId":"2ceea003-59f4-4aa9-a37c-b2af5e4c48be","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v3/pkg/common/cns-lib/node.(*defaultManager).DiscoverNode\n\t/build/pkg/common/cns-lib/node/manager.go:147\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/common/cns-lib/node.(*defaultManager).RegisterNode\n\t/build/pkg/common/cns-lib/node/manager.go:129\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/common/cns-lib/node.(*Nodes).nodeAdd\n\t/build/pkg/common/cns-lib/node/nodes.go:69\nk8s.io/client-go/tools/cache.ResourceEventHandlerFuncs.OnAdd\n\t/go/pkg/mod/k8s.io/client-go@v0.25.2/tools/cache/controller.go:232\nk8s.io/client-go/tools/cache.(*processorListener).run.func1\n\t/go/pkg/mod/k8s.io/client-go@v0.25.2/tools/cache/shared_informer.go:818\nk8s.io/apimachinery/pkg/util/wait.BackoffUntil.func1\n\t/go/pkg/mod/k8s.io/apimachinery@v0.25.2/pkg/util/wait/wait.go:157\nk8s.io/apimachinery/pkg/util/wait.BackoffUntil\n\t/go/pkg/mod/k8s.io/apimachinery@v0.25.2/pkg/util/wait/wait.go:158\nk8s.io/apimachinery/pkg/util/wait.JitterUntil\n\t/go/pkg/mod/k8s.io/apimachinery@v0.25.2/pkg/util/wait/wait.go:135\nk8s.io/apimachinery/pkg/util/wait.Until\n\t/go/pkg/mod/k8s.io/apimachinery@v0.25.2/pkg/util/wait/wait.go:92\nk8s.io/client-go/tools/cache.(*processorListener).run\n\t/go/pkg/mod/k8s.io/client-go@v0.25.2/tools/cache/shared_informer.go:812\nk8s.io/apimachinery/pkg/util/wait.(*Group).Start.func1\n\t/go/pkg/mod/k8s.io/apimachinery@v0.25.2/pkg/util/wait/wait.go:75"}
2023-03-31T11:33:19.880080141Z {"level":"error","time":"2023-03-31T11:33:19.691763489Z","caller":"node/manager.go:131","msg":"failed to discover VM with uuid: \"420e47c7-ba23-d2a8-6656-526432f8313b\" for node: \"c01057a88824-qual-323-0afbb584\"","TraceId":"2ceea003-59f4-4aa9-a37c-b2af5e4c48be","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v3/pkg/common/cns-lib/node.(*defaultManager).RegisterNode\n\t/build/pkg/common/cns-lib/node/manager.go:131\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/common/cns-lib/node.(*Nodes).nodeAdd\n\t/build/pkg/common/cns-lib/node/nodes.go:69\nk8s.io/client-go/tools/cache.ResourceEventHandlerFuncs.OnAdd\n\t/go/pkg/mod/k8s.io/client-go@v0.25.2/tools/cache/controller.go:232\nk8s.io/client-go/tools/cache.(*processorListener).run.func1\n\t/go/pkg/mod/k8s.io/client-go@v0.25.2/tools/cache/shared_informer.go:818\nk8s.io/apimachinery/pkg/util/wait.BackoffUntil.func1\n\t/go/pkg/mod/k8s.io/apimachinery@v0.25.2/pkg/util/wait/wait.go:157\nk8s.io/apimachinery/pkg/util/wait.BackoffUntil\n\t/go/pkg/mod/k8s.io/apimachinery@v0.25.2/pkg/util/wait/wait.go:158\nk8s.io/apimachinery/pkg/util/wait.JitterUntil\n\t/go/pkg/mod/k8s.io/apimachinery@v0.25.2/pkg/util/wait/wait.go:135\nk8s.io/apimachinery/pkg/util/wait.Until\n\t/go/pkg/mod/k8s.io/apimachinery@v0.25.2/pkg/util/wait/wait.go:92\nk8s.io/client-go/tools/cache.(*processorListener).run\n\t/go/pkg/mod/k8s.io/client-go@v0.25.2/tools/cache/shared_informer.go:812\nk8s.io/apimachinery/pkg/util/wait.(*Group).Start.func1\n\t/go/pkg/mod/k8s.io/apimachinery@v0.25.2/pkg/util/wait/wait.go:75"}
2023-03-31T11:33:19.880082445Z {"level":"warn","time":"2023-03-31T11:33:19.691811169Z","caller":"node/nodes.go:72","msg":"failed to register node:\"c01057a88824-qual-323-0afbb584\". err=virtual machine wasn't found","TraceId":"2ceea003-59f4-4aa9-a37c-b2af5e4c48be"}
2023-03-31T11:33:19.880084559Z {"level":"info","time":"2023-03-31T11:33:19.692076979Z","caller":"vsphere/virtualcentermanager.go:123","msg":"Successfully registered VC atl-qual-vc06.anthos:443"}
2023-03-31T11:33:19.880086253Z {"level":"info","time":"2023-03-31T11:33:19.692285863Z","caller":"node/manager.go:128","msg":"Discovering the node vm using uuid: \"420e8daf-1b9e-e49f-e9f9-2c59ab10c59f\"","TraceId":"c42c3ab6-ed72-4328-9ec1-ea34824bdbd4"}
2023-03-31T11:33:19.880088266Z {"level":"info","time":"2023-03-31T11:33:19.692375572Z","caller":"vsphere/virtualmachine.go:159","msg":"Initiating asynchronous datacenter listing with uuid 420e8daf-1b9e-e49f-e9f9-2c59ab10c59f","TraceId":"c42c3ab6-ed72-4328-9ec1-ea34824bdbd4"}
2023-03-31T11:33:19.880090110Z {"level":"info","time":"2023-03-31T11:33:19.692324796Z","caller":"vsphere/virtualcenter.go:283","msg":"VirtualCenter.connect() creating new client"}
divyenpatel
gabrieletosca
lethargosapatheia
k8s-ci-robot
vdkotkar
vu3oim
qdrddr
k8s-triage-robot
/kind bug
What happened: Trying to install vSphere CSI drivers v2.7.0 with RKE2 cluster v1.24.10+rke2r1.
$ cat /etc/rancher/rke2/config.yaml cloud-provider-name: external
_$ cat csi-vsphere.conf [Global] cluster-id = "${CLUSTER_NAME}" cluster-distribution = "Kubernetes"
[VirtualCenter "172.16.16.110"] insecure-flag = "true" user = "user1@vsphere.local" password = "password12345" port = "443" datacenters = "datacenter1"_
_root@urnpk8sm60:~# kubectl --namespace=vmware-system-csi get all NAME READY STATUS RESTARTS AGE pod/vsphere-csi-controller-7589ccbcf8-6w7pw 0/7 Pending 0 3m2s pod/vsphere-csi-controller-7589ccbcf8-phl5c 0/7 Pending 0 3m2s pod/vsphere-csi-controller-7589ccbcf8-wwwfc 0/7 Pending 0 3m2s pod/vsphere-csi-node-6vljg 2/3 CrashLoopBackOff 4 (79s ago) 3m2s pod/vsphere-csi-node-dpnh9 2/3 CrashLoopBackOff 5 (7s ago) 3m2s pod/vsphere-csi-node-jd4wt 2/3 CrashLoopBackOff 4 (78s ago) 3m2s pod/vsphere-csi-node-wtlp7 2/3 CrashLoopBackOff 4 (72s ago) 3m2s
NAME TYPE CLUSTER-IP EXTERNAL-IP PORT(S) AGE service/vsphere-csi-controller ClusterIP 10.43.162.210 2112/TCP,2113/TCP 3m2s
NAME DESIRED CURRENT READY UP-TO-DATE AVAILABLE NODE SELECTOR AGE daemonset.apps/vsphere-csi-node 4 4 0 4 0 kubernetes.io/os=linux 3m2s daemonset.apps/vsphere-csi-node-windows 0 0 0 0 0 kubernetes.io/os=windows 3m2s
NAME READY UP-TO-DATE AVAILABLE AGE deployment.apps/vsphere-csi-controller 0/3 3 0 3m2s
NAME DESIRED CURRENT READY AGE replicaset.apps/vsphere-csi-controller-7589ccbcf8 3 3 0 3m2s root@urnpk8sm60:~#_
root@urnpk8sm60:~# kubectl --namespace=vmware-system-csi logs pod/vsphere-csi-node-wtlp7 Defaulted container "node-driver-registrar" out of: node-driver-registrar, vsphere-csi-node, liveness-probe I0315 11:27:48.852737 1 main.go:166] Version: v2.5.1 I0315 11:27:48.852835 1 main.go:167] Running node-driver-registrar in mode=registration I0315 11:27:48.854993 1 main.go:191] Attempting to open a gRPC connection with: "/csi/csi.sock" I0315 11:27:48.855119 1 connection.go:154] Connecting to unix:///csi/csi.sock I0315 11:27:48.859495 1 main.go:198] Calling CSI driver to discover driver name I0315 11:27:48.859554 1 connection.go:183] GRPC call: /csi.v1.Identity/GetPluginInfo I0315 11:27:48.859566 1 connection.go:184] GRPC request: {} I0315 11:27:48.875719 1 connection.go:186] GRPC response: {"name":"csi.vsphere.vmware.com","vendor_version":"v2.7.0"} I0315 11:27:48.876170 1 connection.go:187] GRPC error: <nil> I0315 11:27:48.876774 1 main.go:208] CSI driver name: "csi.vsphere.vmware.com" I0315 11:27:48.877323 1 node_register.go:53] Starting Registration Server at: /registration/csi.vsphere.vmware.com-reg.sock I0315 11:27:48.878695 1 node_register.go:62] Registration Server started at: /registration/csi.vsphere.vmware.com-reg.sock I0315 11:27:48.879412 1 node_register.go:92] Skipping HTTP server because endpoint is set to: "" I0315 11:27:49.996391 1 main.go:102] Received GetInfo call: &InfoRequest{} I0315 11:27:49.998477 1 main.go:109] "Kubelet registration probe created" path="/var/lib/kubelet/plugins/csi.vsphere.vmware.com/registration" I0315 11:27:50.069958 1 main.go:120] Received NotifyRegistrationStatus call: &RegistrationStatus{PluginRegistered:false,Error:RegisterPlugin error -- plugin registration failed with err: rpc error: code = Internal desc = failed to get CsiNodeTopology for the node: "urnpk8sm60". Error: no matches for kind "CSINodeTopology" in version "cns.vmware.com/v1alpha1",} E0315 11:27:50.070058 1 main.go:122] Registration process failed with error: RegisterPlugin error -- plugin registration failed with err: rpc error: code = Internal desc = failed to get CsiNodeTopology for the node: "urnpk8sm60". Error: no matches for kind "CSINodeTopology" in version "cns.vmware.com/v1alpha1", restarting registration container. root@urnpk8sm60:~#After changing improved-volume-topology: 'true' to false in vsphere-csi-driver.yaml, pod/vsphere-csi-node are running but pod/vsphere-csi-controller are still in Pending state due to node affinity/selector.
Warning FailedScheduling 26s default-scheduler 0/4 nodes are available: 4 node(s) didn't match Pod's node affinity/selector. preemption: 0/4 nodes are available: 4 Preemption is not helpful for scheduling.
What you expected to happen: Same steps are working fine with vanilla Kubernetes but not working with RKE2.
Environment:
uname -a): 5.15.0-60-generic