Trident: Long delay to publish PVs

[bcdonadio]

Hello.

We're experiencing a long delay (>5m) from creating a PVC to having the PV properly mounted in the container and ready to go. As far as we could understand from the logs, trident-main from the Deployment is taking an enormous time (around 2min) to actually start the volume publish process. This causes other retry loops on Kube to back off trying to mount the created PV, resulting in the around 5min period or more to actually deploy something.

We are using Trident 20.04.0 on Kubernetes 1.17.6, connecting to a FAS8040 running ONTAP 9.3P18. CPU usage on all containers is minimal, so there seems to be no kind of busy-loop happening.

Here's the Kube event timeline:

FirstSeen              LastSeen               Count    From                                                                                     Type      Reason                   Message
2020-07-22T23:02:35Z   2020-07-22T23:02:35Z   1        persistentvolume-controller                                                              Normal    ExternalProvisioning     waiting for a volume to be created, either by external provisioner "csi.trident.netapp.io" or manually created by system administrator
2020-07-22T23:02:35Z   2020-07-22T23:02:35Z   1        csi.trident.netapp.io_trident-csi-96f94dcf7-qj2qq_1d9d6c1b-bdb5-47f9-bffa-54f0bdf960b5   Normal    Provisioning             External provisioner is provisioning volume for claim "tridentdelay/trident-claim"
2020-07-22T23:02:35Z   2020-07-22T23:02:35Z   1        statefulset-controller                                                                   Normal    SuccessfulCreate         create Pod rwxtest-0 in StatefulSet rwxtest successful
<nil>                  <nil>                  <none>   default-scheduler                                                                        Warning   FailedScheduling         error while running "VolumeBinding" filter plugin for pod "rwxtest-0": pod has unbound immediate PersistentVolumeClaims
<nil>                  <nil>                  <none>   default-scheduler                                                                        Warning   FailedScheduling         error while running "VolumeBinding" filter plugin for pod "rwxtest-0": pod has unbound immediate PersistentVolumeClaims
2020-07-22T23:02:38Z   2020-07-22T23:02:38Z   1        csi.trident.netapp.io                                                                    Normal    ProvisioningSuccess      provisioned a volume
<nil>                  <nil>                  <none>   default-scheduler                                                                        Warning   FailedScheduling         error while running "VolumeBinding" filter plugin for pod "rwxtest-0": pod has unbound immediate PersistentVolumeClaims
2020-07-22T23:02:38Z   2020-07-22T23:02:38Z   1        csi.trident.netapp.io_trident-csi-96f94dcf7-qj2qq_1d9d6c1b-bdb5-47f9-bffa-54f0bdf960b5   Normal    ProvisioningSucceeded    Successfully provisioned volume pvc-3c898f34-0acf-4e8e-a954-952c08d604b5
<nil>                  <nil>                  <none>   default-scheduler                                                                        Normal    Scheduled                Successfully assigned tridentdelay/rwxtest-0 to app-worker-hq10
2020-07-22T23:04:43Z   2020-07-22T23:04:43Z   1        kubelet                                                                                  Warning   FailedMount              Unable to attach or mount volumes: unmounted volumes=[mainpv], unattached volumes=[default-token-zjwzc mainpv]: timed out waiting for the condition
2020-07-22T23:04:43Z   2020-07-22T23:07:01Z   2        kubelet                                                                                  Warning   FailedMount              Unable to attach or mount volumes: unmounted volumes=[mainpv], unattached volumes=[default-token-zjwzc mainpv]: timed out waiting for the condition
2020-07-22T23:05:52Z   2020-07-22T23:05:52Z   1        attachdetach-controller                                                                  Normal    SuccessfulAttachVolume   AttachVolume.Attach succeeded for volume "pvc-3c898f34-0acf-4e8e-a954-952c08d604b5"
2020-07-22T23:08:54Z   2020-07-22T23:08:54Z   1        kubelet                                                                                  Normal    Pulling                  Pulling image "nginx"
2020-07-22T23:08:54Z   2020-07-22T23:08:54Z   1        kubelet                                                                                  Normal    Pulled                   Successfully pulled image "nginx"
2020-07-22T23:08:54Z   2020-07-22T23:08:54Z   1        kubelet                                                                                  Normal    Created                  Created container main
2020-07-22T23:08:54Z   2020-07-22T23:08:54Z   1        kubelet                                                                                  Normal    Started                  Started container main
2020-07-22T23:08:54Z   2020-07-22T23:08:54Z   1        statefulset-controller                                                                   Normal    SuccessfulCreate         create Pod rwxtest-1 in StatefulSet rwxtest successful
<nil>                  <nil>                  <none>   default-scheduler                                                                        Normal    Scheduled                Successfully assigned tridentdelay/rwxtest-1 to app-worker-hq10
2020-07-22T23:08:56Z   2020-07-22T23:08:56Z   1        kubelet                                                                                  Normal    Pulling                  Pulling image "nginx"
2020-07-22T23:08:57Z   2020-07-22T23:08:57Z   1        kubelet                                                                                  Normal    Pulled                   Successfully pulled image "nginx"
2020-07-22T23:08:57Z   2020-07-22T23:08:57Z   1        kubelet                                                                                  Normal    Created                  Created container main
2020-07-22T23:08:57Z   2020-07-22T23:08:57Z   1        kubelet                                                                                  Normal    Started                  Started container main
2020-07-22T23:08:57Z   2020-07-22T23:08:57Z   1        statefulset-controller                                                                   Normal    SuccessfulCreate         create Pod rwxtest-2 in StatefulSet rwxtest successful
<nil>                  <nil>                  <none>   default-scheduler                                                                        Normal    Scheduled                Successfully assigned tridentdelay/rwxtest-2 to app-worker-hq10
2020-07-22T23:08:59Z   2020-07-22T23:08:59Z   1        kubelet                                                                                  Normal    Pulling                  Pulling image "nginx"
2020-07-22T23:08:59Z   2020-07-22T23:08:59Z   1        kubelet                                                                                  Normal    Pulled                   Successfully pulled image "nginx"
2020-07-22T23:08:59Z   2020-07-22T23:08:59Z   1        kubelet                                                                                  Normal    Created                  Created container main
2020-07-22T23:08:59Z   2020-07-22T23:08:59Z   1        kubelet                                                                                  Normal    Started                  Started container main

Logs from the Deployment pod containers:

Manifests used to reproduce the issue: https://gist.github.com/bcdonadio/ccdb9b06aa83cb96f0ac6e2056fb895f
StorageClass used: https://gist.github.com/bcdonadio/446c073ae089c8ea551caa044768b9ee

Any idea of what might be happening?

[bcdonadio]

I made a sequence diagram of the messages sent between CSI components with the timing. Hope this helps to navigate the issue.

[benlangfeld]

@clintonk Is there an ETA on this being addressed? Trident (and therefore our NetApp hardware) are basically unusable with these sort of bugs.

[gnarl]

Hi @benlangfeld and @bcdonadio,

Thanks for providing the detailed information. I've reviewed the logs you've provided with the team and we don't see a delay with anything that Trident is responsible for doing. I suggest checking your Kubernetes logs to determine where the delay is occurring. The first delay of 1m 55s is a little unusual in that K8S can typically take up to a minute to send a GRPC call. Since it is almost 2 minutes it might mean that there was a communication failure with the first attempt and then K8S tried again.

For the 4m 19s delay it may again be communications failures or it took a while to schedule the pod before K8S called Trident to stage the volume.

We'd be interested in knowing what you find. If you do need additional assistance please open a NetApp support case.

[bcdonadio]

Hello @gnarl.

I've setup another VM with Kind (new clean cluster) using the same Kubernetes version in the exact same network as the other nodes (which are also virtualized) and connected to the same ONTAP appliance with the exact same TridentBackend configs and StorageClasses. I was not able to reproduce the issue. There are no indications anywhere in the cluster or elsewhere in the network of communications issues.

This keeps pointing to be a bad behaviour because of some strange state kept in Trident's persistence of that cluster. Any idea what could that be, or how to further debug it?

Thank you.

[gnarl]

Hi @bcdonadio,

When we reviewed the Trident logs it was seen that there wasn't any delay in processing the received requests. The 1m55s delay and the 4m19s delay from your sequence diagram occurred outside of Trident. If you are unable to replicate the issue then it sounds like an issue in the original K8S cluster setup. If you are still seeing that behavior I'd recommend testing for network connectivity and packet drop between the Kube API server, the node running the Trident controller, and the individual work nodes. You can also open a NetApp support case where additional support can be provided.

[bcdonadio]

Hi @gnarl.

NetApp's main support channel is barely aware that Trident is even a thing. We had a bad time before trying to get someone which would know Kubernetes at all.

We found something interesting in the kubelet logs:

Aug 06 19:12:59 app-worker-hq10 kubelet[1609]: I0806 19:12:59.372732    1609 reconciler.go:209] operationExecutor.VerifyControllerAttachedVolume started for volume "default-token-jftng" (UniqueName: "kubernetes.io/secret/0c14d4c1-cd7c-46ea-a084-91b64f8eca75-default-token-jftng") pod "tridentdelay-0" (UID: "0c14d4c1-cd7c-46ea-a084-91b64f8eca75")
Aug 06 19:12:59 app-worker-hq10 kubelet[1609]: I0806 19:12:59.372806    1609 reconciler.go:209] operationExecutor.VerifyControllerAttachedVolume started for volume "pvc-fae28e30-4522-4fff-9dba-752b80ee84a2" (UniqueName: "kubernetes.io/csi/csi.trident.netapp.io^pvc-fae28e30-4522-4fff-9dba-752b80ee84a2") pod "tridentdelay-0" (UID: "0c14d4c1-cd7c-46ea-a084-91b64f8eca75")
Aug 06 19:12:59 app-worker-hq10 kubelet[1609]: E0806 19:12:59.372881    1609 nestedpendingoperations.go:301] Operation for "{volumeName:kubernetes.io/csi/csi.trident.netapp.io^pvc-fae28e30-4522-4fff-9dba-752b80ee84a2 podName: nodeName:}" failed. No retries permitted until 2020-08-06 19:12:59.872842071 +0000 UTC m=+11456.603429891 (durationBeforeRetry 500ms). Error: "Volume has not been added to the list of VolumesInUse in the node's volume status for volume \"pvc-fae28e30-4522-4fff-9dba-752b80ee84a2\" (UniqueName: \"kubernetes.io/csi/csi.trident.netapp.io^pvc-fae28e30-4522-4fff-9dba-752b80ee84a2\") pod \"tridentdelay-0\" (UID: \"0c14d4c1-cd7c-46ea-a084-91b64f8eca75\") "
Aug 06 19:12:59 app-worker-hq10 kubelet[1609]: I0806 19:12:59.874383    1609 reconciler.go:209] operationExecutor.VerifyControllerAttachedVolume started for volume "pvc-fae28e30-4522-4fff-9dba-752b80ee84a2" (UniqueName: "kubernetes.io/csi/csi.trident.netapp.io^pvc-fae28e30-4522-4fff-9dba-752b80ee84a2") pod "tridentdelay-0" (UID: "0c14d4c1-cd7c-46ea-a084-91b64f8eca75")
Aug 06 19:12:59 app-worker-hq10 kubelet[1609]: E0806 19:12:59.874493    1609 nestedpendingoperations.go:301] Operation for "{volumeName:kubernetes.io/csi/csi.trident.netapp.io^pvc-fae28e30-4522-4fff-9dba-752b80ee84a2 podName: nodeName:}" failed. No retries permitted until 2020-08-06 19:13:00.874463547 +0000 UTC m=+11457.605051382 (durationBeforeRetry 1s). Error: "Volume has not been added to the list of VolumesInUse in the node's volume status for volume \"pvc-fae28e30-4522-4fff-9dba-752b80ee84a2\" (UniqueName: \"kubernetes.io/csi/csi.trident.netapp.io^pvc-fae28e30-4522-4fff-9dba-752b80ee84a2\") pod \"tridentdelay-0\" (UID: \"0c14d4c1-cd7c-46ea-a084-91b64f8eca75\") "
Aug 06 19:13:00 app-worker-hq10 kubelet[1609]: I0806 19:13:00.878035    1609 reconciler.go:209] operationExecutor.VerifyControllerAttachedVolume started for volume "pvc-fae28e30-4522-4fff-9dba-752b80ee84a2" (UniqueName: "kubernetes.io/csi/csi.trident.netapp.io^pvc-fae28e30-4522-4fff-9dba-752b80ee84a2") pod "tridentdelay-0" (UID: "0c14d4c1-cd7c-46ea-a084-91b64f8eca75")
Aug 06 19:13:02 app-worker-hq10 kubelet[1609]: I0806 19:13:02.885637    1609 reconciler.go:209] operationExecutor.VerifyControllerAttachedVolume started for volume "pvc-fae28e30-4522-4fff-9dba-752b80ee84a2" (UniqueName: "kubernetes.io/csi/csi.trident.netapp.io^pvc-fae28e30-4522-4fff-9dba-752b80ee84a2") pod "tridentdelay-0" (UID: "0c14d4c1-cd7c-46ea-a084-91b64f8eca75")
Aug 06 19:13:02 app-worker-hq10 kubelet[1609]: E0806 19:13:02.892348    1609 nestedpendingoperations.go:301] Operation for "{volumeName:kubernetes.io/csi/csi.trident.netapp.io^pvc-fae28e30-4522-4fff-9dba-752b80ee84a2 podName: nodeName:}" failed. No retries permitted until 2020-08-06 19:13:06.892322207 +0000 UTC m=+11463.622910042 (durationBeforeRetry 4s). Error: "Volume not attached according to node status for volume \"pvc-fae28e30-4522-4fff-9dba-752b80ee84a2\" (UniqueName: \"kubernetes.io/csi/csi.trident.netapp.io^pvc-fae28e30-4522-4fff-9dba-752b80ee84a2\") pod \"tridentdelay-0\" (UID: \"0c14d4c1-cd7c-46ea-a084-91b64f8eca75\") "
Aug 06 19:13:06 app-worker-hq10 kubelet[1609]: I0806 19:13:06.900815    1609 reconciler.go:209] operationExecutor.VerifyControllerAttachedVolume started for volume "pvc-fae28e30-4522-4fff-9dba-752b80ee84a2" (UniqueName: "kubernetes.io/csi/csi.trident.netapp.io^pvc-fae28e30-4522-4fff-9dba-752b80ee84a2") pod "tridentdelay-0" (UID: "0c14d4c1-cd7c-46ea-a084-91b64f8eca75")
Aug 06 19:13:06 app-worker-hq10 kubelet[1609]: E0806 19:13:06.908078    1609 nestedpendingoperations.go:301] Operation for "{volumeName:kubernetes.io/csi/csi.trident.netapp.io^pvc-fae28e30-4522-4fff-9dba-752b80ee84a2 podName: nodeName:}" failed. No retries permitted until 2020-08-06 19:13:14.908048009 +0000 UTC m=+11471.638635838 (durationBeforeRetry 8s). Error: "Volume not attached according to node status for volume \"pvc-fae28e30-4522-4fff-9dba-752b80ee84a2\" (UniqueName: \"kubernetes.io/csi/csi.trident.netapp.io^pvc-fae28e30-4522-4fff-9dba-752b80ee84a2\") pod \"tridentdelay-0\" (UID: \"0c14d4c1-cd7c-46ea-a084-91b64f8eca75\") "
Aug 06 19:13:08 app-worker-hq10 kubelet[1609]: W0806 19:13:08.306284    1609 volume_linux.go:45] Setting volume ownership for /var/lib/kubelet/pods/71d6a06d-aee2-4dcd-94f8-7f775031e7e1/volumes/kubernetes.io~secret/prometheus-operator-prometheus-node-exporter-token-z9p4f and fsGroup set. If the volume has a lot of files then setting volume ownership could be slow, see https://github.com/kubernetes/kubernetes/issues/69699
Aug 06 19:13:14 app-worker-hq10 kubelet[1609]: I0806 19:13:14.932085    1609 reconciler.go:209] operationExecutor.VerifyControllerAttachedVolume started for volume "pvc-fae28e30-4522-4fff-9dba-752b80ee84a2" (UniqueName: "kubernetes.io/csi/csi.trident.netapp.io^pvc-fae28e30-4522-4fff-9dba-752b80ee84a2") pod "tridentdelay-0" (UID: "0c14d4c1-cd7c-46ea-a084-91b64f8eca75")
Aug 06 19:13:14 app-worker-hq10 kubelet[1609]: E0806 19:13:14.939280    1609 nestedpendingoperations.go:301] Operation for "{volumeName:kubernetes.io/csi/csi.trident.netapp.io^pvc-fae28e30-4522-4fff-9dba-752b80ee84a2 podName: nodeName:}" failed. No retries permitted until 2020-08-06 19:13:30.939252009 +0000 UTC m=+11487.669839869 (durationBeforeRetry 16s). Error: "Volume not attached according to node status for volume \"pvc-fae28e30-4522-4fff-9dba-752b80ee84a2\" (UniqueName: \"kubernetes.io/csi/csi.trident.netapp.io^pvc-fae28e30-4522-4fff-9dba-752b80ee84a2\") pod \"tridentdelay-0\" (UID: \"0c14d4c1-cd7c-46ea-a084-91b64f8eca75\") "
Aug 06 19:13:30 app-worker-hq10 kubelet[1609]: I0806 19:13:30.994042    1609 reconciler.go:209] operationExecutor.VerifyControllerAttachedVolume started for volume "pvc-fae28e30-4522-4fff-9dba-752b80ee84a2" (UniqueName: "kubernetes.io/csi/csi.trident.netapp.io^pvc-fae28e30-4522-4fff-9dba-752b80ee84a2") pod "tridentdelay-0" (UID: "0c14d4c1-cd7c-46ea-a084-91b64f8eca75")
Aug 06 19:13:31 app-worker-hq10 kubelet[1609]: E0806 19:13:31.002030    1609 nestedpendingoperations.go:301] Operation for "{volumeName:kubernetes.io/csi/csi.trident.netapp.io^pvc-fae28e30-4522-4fff-9dba-752b80ee84a2 podName: nodeName:}" failed. No retries permitted until 2020-08-06 19:14:03.001966596 +0000 UTC m=+11519.732554496 (durationBeforeRetry 32s). Error: "Volume not attached according to node status for volume \"pvc-fae28e30-4522-4fff-9dba-752b80ee84a2\" (UniqueName: \"kubernetes.io/csi/csi.trident.netapp.io^pvc-fae28e30-4522-4fff-9dba-752b80ee84a2\") pod \"tridentdelay-0\" (UID: \"0c14d4c1-cd7c-46ea-a084-91b64f8eca75\") "
Aug 06 19:14:03 app-worker-hq10 kubelet[1609]: I0806 19:14:03.023262    1609 reconciler.go:209] operationExecutor.VerifyControllerAttachedVolume started for volume "pvc-fae28e30-4522-4fff-9dba-752b80ee84a2" (UniqueName: "kubernetes.io/csi/csi.trident.netapp.io^pvc-fae28e30-4522-4fff-9dba-752b80ee84a2") pod "tridentdelay-0" (UID: "0c14d4c1-cd7c-46ea-a084-91b64f8eca75")
Aug 06 19:14:03 app-worker-hq10 kubelet[1609]: E0806 19:14:03.030753    1609 nestedpendingoperations.go:301] Operation for "{volumeName:kubernetes.io/csi/csi.trident.netapp.io^pvc-fae28e30-4522-4fff-9dba-752b80ee84a2 podName: nodeName:}" failed. No retries permitted until 2020-08-06 19:15:07.030693543 +0000 UTC m=+11583.761281436 (durationBeforeRetry 1m4s). Error: "Volume not attached according to node status for volume \"pvc-fae28e30-4522-4fff-9dba-752b80ee84a2\" (UniqueName: \"kubernetes.io/csi/csi.trident.netapp.io^pvc-fae28e30-4522-4fff-9dba-752b80ee84a2\") pod \"tridentdelay-0\" (UID: \"0c14d4c1-cd7c-46ea-a084-91b64f8eca75\") "
Aug 06 19:14:18 app-worker-hq10 kubelet[1609]: W0806 19:14:18.279703    1609 volume_linux.go:45] Setting volume ownership for /var/lib/kubelet/pods/71d6a06d-aee2-4dcd-94f8-7f775031e7e1/volumes/kubernetes.io~secret/prometheus-operator-prometheus-node-exporter-token-z9p4f and fsGroup set. If the volume has a lot of files then setting volume ownership could be slow, see https://github.com/kubernetes/kubernetes/issues/69699
Aug 06 19:15:02 app-worker-hq10 kubelet[1609]: E0806 19:15:02.197130    1609 kubelet.go:1680] Unable to attach or mount volumes for pod "tridentdelay-0_tridentdelay(0c14d4c1-cd7c-46ea-a084-91b64f8eca75)": unmounted volumes=[mainpv], unattached volumes=[mainpv default-token-jftng]: timed out waiting for the condition; skipping pod
Aug 06 19:15:02 app-worker-hq10 kubelet[1609]: E0806 19:15:02.197224    1609 pod_workers.go:191] Error syncing pod 0c14d4c1-cd7c-46ea-a084-91b64f8eca75 ("tridentdelay-0_tridentdelay(0c14d4c1-cd7c-46ea-a084-91b64f8eca75)"), skipping: unmounted volumes=[mainpv], unattached volumes=[mainpv default-token-jftng]: timed out waiting for the condition
Aug 06 19:15:03 app-worker-hq10 kubelet[1609]: E0806 19:15:03.182152    1609 kubelet_volumes.go:154] orphaned pod "000aa083-68db-4a82-b7cf-180eb8ecc0a4" found, but volume paths are still present on disk : There were a total of 11 errors similar to this. Turn up verbosity to see them.
Aug 06 19:15:05 app-worker-hq10 kubelet[1609]: E0806 19:15:05.186480    1609 kubelet_volumes.go:154] orphaned pod "000aa083-68db-4a82-b7cf-180eb8ecc0a4" found, but volume paths are still present on disk : There were a total of 11 errors similar to this. Turn up verbosity to see them.
Aug 06 19:15:07 app-worker-hq10 kubelet[1609]: I0806 19:15:07.067384    1609 reconciler.go:209] operationExecutor.VerifyControllerAttachedVolume started for volume "pvc-fae28e30-4522-4fff-9dba-752b80ee84a2" (UniqueName: "kubernetes.io/csi/csi.trident.netapp.io^pvc-fae28e30-4522-4fff-9dba-752b80ee84a2") pod "tridentdelay-0" (UID: "0c14d4c1-cd7c-46ea-a084-91b64f8eca75")
Aug 06 19:15:07 app-worker-hq10 kubelet[1609]: I0806 19:15:07.074598    1609 operation_generator.go:1245] Controller attach succeeded for volume "pvc-fae28e30-4522-4fff-9dba-752b80ee84a2" (UniqueName: "kubernetes.io/csi/csi.trident.netapp.io^pvc-fae28e30-4522-4fff-9dba-752b80ee84a2") pod "tridentdelay-0" (UID: "0c14d4c1-cd7c-46ea-a084-91b64f8eca75") device path: ""
Aug 06 19:15:07 app-worker-hq10 kubelet[1609]: I0806 19:15:07.168370    1609 operation_generator.go:551] MountVolume.WaitForAttach entering for volume "pvc-fae28e30-4522-4fff-9dba-752b80ee84a2" (UniqueName: "kubernetes.io/csi/csi.trident.netapp.io^pvc-fae28e30-4522-4fff-9dba-752b80ee84a2") pod "tridentdelay-0" (UID: "0c14d4c1-cd7c-46ea-a084-91b64f8eca75") DevicePath ""
Aug 06 19:15:07 app-worker-hq10 kubelet[1609]: I0806 19:15:07.174554    1609 operation_generator.go:560] MountVolume.WaitForAttach succeeded for volume "pvc-fae28e30-4522-4fff-9dba-752b80ee84a2" (UniqueName: "kubernetes.io/csi/csi.trident.netapp.io^pvc-fae28e30-4522-4fff-9dba-752b80ee84a2") pod "tridentdelay-0" (UID: "0c14d4c1-cd7c-46ea-a084-91b64f8eca75") DevicePath "csi-9a5adc53b6ff0b1dab2c4e550316b453088494c2f8bab34b56e3c5beeaae3458"
Aug 06 19:15:07 app-worker-hq10 kubelet[1609]: I0806 19:15:07.174912    1609 clientconn.go:104] parsed scheme: ""
Aug 06 19:15:07 app-worker-hq10 kubelet[1609]: I0806 19:15:07.174934    1609 clientconn.go:104] scheme "" not registered, fallback to default scheme
Aug 06 19:15:07 app-worker-hq10 kubelet[1609]: I0806 19:15:07.174957    1609 passthrough.go:48] ccResolverWrapper: sending update to cc: {[{/var/lib/kubelet/plugins/csi.trident.netapp.io/csi.sock 0  <nil>}] <nil>}
Aug 06 19:15:07 app-worker-hq10 kubelet[1609]: I0806 19:15:07.174971    1609 clientconn.go:577] ClientConn switching balancer to "pick_first"
Aug 06 19:15:07 app-worker-hq10 kubelet[1609]: I0806 19:15:07.181866    1609 clientconn.go:104] parsed scheme: ""
Aug 06 19:15:07 app-worker-hq10 kubelet[1609]: I0806 19:15:07.181889    1609 clientconn.go:104] scheme "" not registered, fallback to default scheme
Aug 06 19:15:07 app-worker-hq10 kubelet[1609]: I0806 19:15:07.181906    1609 passthrough.go:48] ccResolverWrapper: sending update to cc: {[{/var/lib/kubelet/plugins/csi.trident.netapp.io/csi.sock 0  <nil>}] <nil>}
Aug 06 19:15:07 app-worker-hq10 kubelet[1609]: I0806 19:15:07.181915    1609 clientconn.go:577] ClientConn switching balancer to "pick_first"
Aug 06 19:15:07 app-worker-hq10 kubelet[1609]: I0806 19:15:07.186879    1609 operation_generator.go:587] MountVolume.MountDevice succeeded for volume "pvc-fae28e30-4522-4fff-9dba-752b80ee84a2" (UniqueName: "kubernetes.io/csi/csi.trident.netapp.io^pvc-fae28e30-4522-4fff-9dba-752b80ee84a2") pod "tridentdelay-0" (UID: "0c14d4c1-cd7c-46ea-a084-91b64f8eca75") device mount path "/var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-fae28e30-4522-4fff-9dba-752b80ee84a2/globalmount"
Aug 06 19:15:07 app-worker-hq10 kubelet[1609]: E0806 19:15:07.187205    1609 kubelet_volumes.go:154] orphaned pod "000aa083-68db-4a82-b7cf-180eb8ecc0a4" found, but volume paths are still present on disk : There were a total of 11 errors similar to this. Turn up verbosity to see them.
Aug 06 19:15:07 app-worker-hq10 kubelet[1609]: I0806 19:15:07.193557    1609 clientconn.go:104] parsed scheme: ""
Aug 06 19:15:07 app-worker-hq10 kubelet[1609]: I0806 19:15:07.193578    1609 clientconn.go:104] scheme "" not registered, fallback to default scheme
Aug 06 19:15:07 app-worker-hq10 kubelet[1609]: I0806 19:15:07.193593    1609 passthrough.go:48] ccResolverWrapper: sending update to cc: {[{/var/lib/kubelet/plugins/csi.trident.netapp.io/csi.sock 0  <nil>}] <nil>}

Any idea why the kubelet is failing to talk with Trident in the same node? This is clearly not a network issue.

Thank you for your efforts on trying to solve this.

[crossond]

@bcdonadio
To open a case with NetApp, please go to https://mysupport.netapp.com/site/.
Bottom left, Click on 'Contact Support'
Find the appropriate number from your region to call in, or login.
Note: Trident is not listed on the page, but is a supported product by NetApp based on a supported Netapp storage SN.
Open the case on the NetApp storage SN, and provide the description of the problem.
Be sure to mention the product is Trident on Kubernetes, and provide the details. Mention this GitHub.
The case will be directed to Trident support engineers for response.
Hope this is helpful.

[gnarl]

All,

If you think you are experiencing this issue please open a NetApp support case so that we can help determine where the issue exists.

[gnarl]

@bcdonadio,

It appears that there is a known issue in Kubernetes that can cause a long delay in detach/attach of a PV. This has been fixed in later K8S patch versions.

[bklang]

Hi @gnarl - Thank you for your support diagnosing this issue. We did upgrade Kubernetes and found it resolved the PV delays for us. This issue can be closed.

[gnarl]

@bklang, thanks for the update!

[khankth]

Hi @gnarl - Thank you for your support diagnosing this issue. We did upgrade Kubernetes and found it resolved the PV delays for us. This issue can be closed.

Hi @bklang
Thanks for the update, we are encountering similar issue with Kubernetes 1.18.4, which release did you upgrade to?

[benlangfeld]

@khankth v1.17.9

[ledroide]

We had a similar issue. The root cause was a nameserver, set in resolve.conf, that was unreachable from nodes.