Trident: ReconcileNodeAccess of ontap-san fails and causes CrashLoopBackoff in Trident 21.10.0

Created on 4 Nov 2021  ·  7Comments  ·  Source: NetApp/trident

Describe the bug
ReconcileNodeAccess of ontap-san fails and causes CrashLoopBackoff in Trident 21.10.0.

time="2021-11-04T06:25:58Z" level=error msg="Trident initialization failed; error removing IQN ${IQN}, Reason: LUN maps for this initiator group exist, Code: 9029"

$ kubectl get pod -n trident -l app=controller.csi.trident.netapp.io
NAME                           READY   STATUS             RESTARTS   AGE
trident-csi-7b7464695d-kp84m   2/6     CrashLoopBackOff   64         49m

I found that the force flag of IgroupRemove, which was true in Trident 20.07.2, was changed to false in Trident 21.10.0. I am not sure this change was intentional, but I think it might cause the problem.

Here is the related log of the Trident controller plugin. (Sensitive values were masked.)

$ kubectl logs -n trident deploy/trident-csi trident-main | grep error | head -5
time="2021-11-04T06:25:58Z" level=error msg="Trident initialization failed; error removing IQN ${IQN} from igroup ${IGROUP}: error removing IQN ${IQN}, Reason: LUN maps for this initiator group exist, Code: 9029"
time="2021-11-04T06:25:58Z" level=error msg="error cleaning up previously failed PV upgrades; could not list known volumes; Trident initialization failed; error removing IQN ${IQN} from igroup ${IGROUP}: error removing IQN ${IQN} from igroup ${IGROUP}: API status: failed, Reason: LUN maps for this initiator group exist, Code: 9029"
time="2021-11-04T06:25:58Z" level=warning msg="K8S helper could not add a storage class: Trident initialization failed; error removing IQN ${IQN} from igroup ${IGROUP}: error removing IQN ${IQN}, Reason: LUN maps for this initiator group exist, Code: 9029" name=ontap-block parameters="map[backendType:ontap-san fsType:ext4]" provisioner=csi.trident.netapp.io requestID=7b7e63f5-51b3-4fb4-bf45-307c6e52f89d requestSource=Kubernetes
time="2021-11-04T06:25:58Z" level=warning msg="K8S helper could not add a storage class: Trident initialization failed; error removing IQN ${IQN} from igroup ${IGROUP}: error removing IQN <IMYQN> from igroup ${IGROUP}: API status: failed, Reason: LUN maps for this initiator group exist, Code: 9029" name=ontap-file parameters="map[backendType:ontap-nas]" provisioner=csi.trident.netapp.io requestID=c92a03b7-882a-45c6-b26d-a77e52f6e6d1 requestSource=Kubernetes
time="2021-11-04T06:25:58Z" level=error msg="unable to list nodes in Trident; aborting node reconciliation" err="Trident initialization failed; error removing IQN ${IQN} from igroup ${IGROUP}: error removing IQN ${IQN} from igroup ${IGROUP}: API status: failed, Reason: LUN maps for this initiator group exist, Code: 9029" requestID=7594b815-13a2-4118-9017-8d8f86e392b3 requestSource=Internal

Environment
Provide accurate information about the environment to help us reproduce the issue.

  • Trident version: 21.10.0
  • Trident installation flags used: silenceAutosupport: true (Trident Operator)
  • Container runtime: Docker 20.10.8
  • Kubernetes version: v1.21.1
  • Kubernetes orchestrator: Kubernetes
  • Kubernetes enabled feature gates:
  • OS: Ubuntu 20.04.3
  • NetApp backend types: ONTAP AFF 9.7P13
  • Other:

To Reproduce
Steps to reproduce the behavior:

  • Install Trident 21.10.0
  • Setup ontap-san backend
  • Delete one node
  • Restart the Trident controller plugin

    • kubectl rollout restart -n trident deploy/trident-csi

  • The Trident controller pod will be CrashLoopBackOff

Expected behavior
ReconcileNodeAccess works normally.

Additional context

bug tracked
Source
picture tksm
👍5 👀1

All 7 comments

We observed a similar behaviour when updating trident from v21.07.1 to v21.10.0. After the update we can no longer use our pvcs. Trident controller trident-main complains about initiator groups deletions:

time="2021-11-08T16:02:00Z" level=info msg="Initiator group (igroup) already exists." igroup=exp_kube_trident requestID=740d30c4-ecfc-41e8-9c59-220858063a19 requestSource=Periodic
time="2021-11-08T16:02:00Z" level=error msg="Problem encountered updating node access rules for backend." backend=ontapsan_10.20.50.34 error="error removing IQN iqn.2016-04.com.open-iscsi:128b23244f0 from igroup exp_kube_trident: error removing IQN iqn.2016-04.com.open-iscsi:128b23244f0 from igroup exp_kube_trident: API status: failed, Reason: LUN maps for this initiator group exist, Code: 9029" requestID=740d30c4-ecfc-41e8-9c59-220858063a19 requestSource=Periodic
time="2021-11-08T16:02:30Z" level=info msg="Initiator group (igroup) already exists." igroup=exp_kube_trident requestID=740d30c4-ecfc-41e8-9c59-220858063a19 requestSource=Periodic
time="2021-11-08T16:02:30Z" level=error msg="Problem encountered updating node access rules for backend." backend=ontapsan_10.20.50.34 error="error removing IQN iqn.2016-04.com.open-iscsi:128b23244f0 from igroup exp_kube_trident: error removing IQN iqn.2016-04.com.open-iscsi:128b23244f0 from igroup exp_kube_trident: API status: failed, Reason: LUN maps for this initiator group exist, Code: 9029" requestID=740d30c4-ecfc-41e8-9c59-220858063a19 requestSource=Periodic

and pods with persistent volumes are not able to attach volumes and start, for example:

Events:
  Type     Reason              Age                   From                     Message
  ----     ------              ----                  ----                     -------
  Warning  FailedAttachVolume  23m (x6 over 42m)     attachdetach-controller  AttachVolume.Attach failed for volume "pvc-25390a9b-5767-4a6e-ac28-2af6706299db" : rpc error: code = Internal desc = unable to update node access rules on backend ontapsan_10.20.50.34; error removing IQN iqn.2016-04.com.open-iscsi:dae4de2b94db from igroup exp_kube_trident: error removing IQN iqn.2016-04.com.open-iscsi:dae4de2b94db from igroup exp_kube_trident: API status: failed, Reason: LUN maps for this initiator group exist, Code: 9029
  Warning  FailedMount         14m (x3 over 58m)     kubelet                  Unable to attach or mount volumes: unmounted volumes=[prometheus], unattached volumes=[config-volume config-shared alerts-volume prometheus thanos-storage vault-tls kube-api-access-42466]: timed out waiting for the condition

We had to roll back to make things work again.

ffilippopoulos picture ffilippopoulos on 8 Nov 2021

I believe that the problem is so critical for all NetApp/Trident v21.10.0 + ontapsan users.
This bug occurs in any event of node. (e.g. reboot, add, delete, etc)
Moreover, all Pods using volume in ONTAP will be crash when it operates for volume. (e.g. attach/detach/create/delete, etc)
Therefore, if the user try to use Trident v21.10.0 + ontapsan, they run the risk of all their services going down!

I show simple case.

  1. environment 
$ tridentctl version -n trident
+----------------+----------------+
| SERVER VERSION | CLIENT VERSION |
+----------------+----------------+
| 21.10.0        | 21.10.0        |
+----------------+----------------+

$ tridentctl get backend -n trident
+----------+----------------+--------------------------------------+--------+---------+
|   NAME   | STORAGE DRIVER |                 UUID                 | STATE  | VOLUMES |
+----------+----------------+--------------------------------------+--------+---------+
| ontapsan | ontap-san      | 3dad18d6-d378-46ea-87da-d3bb492e0ffd | online |       1 |
+----------+----------------+--------------------------------------+--------+---------+

$ kubectl get pod -n trident
NAME                           READY   STATUS    RESTARTS   AGE
trident-csi-6d5dbdbf68-fbc9l   6/6     Running   0          7m10s
trident-csi-c4sv4              2/2     Running   0          7m9s
trident-csi-d747l              2/2     Running   0          7m9s
trident-csi-fvrdg              2/2     Running   0          7m9s
trident-csi-k92xq              2/2     Running   0          7m9s
trident-csi-qvtfw              2/2     Running   0          7m9s
trident-csi-wlm9p              2/2     Running   0          7m10s
trident-csi-z28cv              2/2     Running   0          7m9s

$ kubectl get pod,pvc,pv -o wide
NAME            READY   STATUS    RESTARTS   AGE   IP            NODE                                      NOMINATED NODE   READINESS GATES
pod/pv-test-0   1/1     Running   0          87s   10.26.96.17   demo-ysaka-tri-w-default-cda54bbb-ws6wj   <none>           <none>

NAME                                    STATUS   VOLUME                                     CAPACITY    ACCESS MODES   STORAGECLASS   AGE   VOLUMEMODE
persistentvolumeclaim/block-pv-test-0   Bound    pvc-3ae2c873-490d-420d-ad6c-57bfac665c42   9765625Ki   RWO            ontap-block    87s   Filesystem

NAME                                                        CAPACITY    ACCESS MODES   RECLAIM POLICY   STATUS   CLAIM                     STORAGECLASS   REASON   AGE   VOLUMEMODE
persistentvolume/pvc-3ae2c873-490d-420d-ad6c-57bfac665c42   9765625Ki   RWO            Delete           Bound    default/block-pv-test-0   ontap-block             84s   Filesystem
  1. Reboot Node　
  2. Check trident-csi's log
$ kubectl logs trident-csi-6d5dbdbf68-fbc9l trident-main -n trident -f
...
time="2021-11-19T07:47:47Z" level=info msg="Initiator group (igroup) already exists." igroup=ysaka-tri-iscsi-test requestID=8b33284d-2a0b-44fe-b495-076f7c6f5303 requestSource=Kubernetes
time="2021-11-19T07:47:47Z" level=error msg="error deleting node from Trident's database; error removing IQN iqn.1993-08.org.debian:01:387c4b432f1 from igroup ysaka-tri-iscsi-test: error removing IQN iqn.1993-08.org.debian:01:387c4b432f1 from igroup ysaka-tri-iscsi-test: API status: failed, Reason: LUN maps for this initiator group exist, Code: 9029" name=demo-ysaka-tri-w-default-cda54bbb-ws6wj requestID=8b33284d-2a0b-44fe-b495-076f7c6f5303 requestSource=Kubernetes

When "LUN maps for this initiator group exist, Code: 9029" error occur, trident-csi pod is abnormal.

  1. Re-create trident-csi pod
$ kubectl delete pod trident-csi-6d5dbdbf68-fbc9l -n trident
pod "trident-csi-6d5dbdbf68-fbc9l" deleted

$ kubectl get pod -n trident
NAME                           READY   STATUS             RESTARTS     AGE
trident-csi-6d5dbdbf68-r4qsn   2/6     CrashLoopBackOff   8 (9s ago)   40s
trident-csi-d747l              2/2     Running            0            27m
trident-csi-fvrdg              2/2     Running            0            27m
trident-csi-k92xq              2/2     Running            0            27m
trident-csi-qvtfw              2/2     Running            0            27m
trident-csi-sxdvp              2/2     Running            0            7m6s
trident-csi-wlm9p              2/2     Running            0            28m
trident-csi-z28cv              2/2     Running            0            27m

The trident-csi shift to CrashLoopBackOff.

  1. Re-create the pod using volume
$ kubectl delete pod pv-test-0 
pod "pv-test-0" deleted

$ kubectl get pod
NAME        READY   STATUS              RESTARTS   AGE
pv-test-0   0/1     ContainerCreating   0          2m20s

$ kubectl describe pod pv-test-0 
...
Events:
  Type     Reason              Age    From                     Message
  ----     ------              ----   ----                     -------
  Normal   Scheduled           2m24s  default-scheduler        Successfully assigned default/pv-test-0 to demo-ysaka-tri-w-default-cda54bbb-wdmbz
  Warning  FailedAttachVolume  2m24s  attachdetach-controller  Multi-Attach error for volume "pvc-3ae2c873-490d-420d-ad6c-57bfac665c42" Volume is already exclusively attached to one node and can't be attached to another
  Warning  FailedMount         21s    kubelet                  Unable to attach or mount volumes: unmounted volumes=[block], unattached volumes=[block kube-api-access-t62dw]: timed out waiting for the condition
ysakashita picture ysakashita on 19 Nov 2021

Additional.
In CrashLoopBackOff in trident-csi, I cannot use the tridentctl command either.

$ tridentctl version -n trident
Error: exit status 1; Error: could not get version: Trident initialization failed; error removing IQN iqn.1993-08.org.debian:01:387c4b432f1 from igroup ysaka-tri-iscsi-test: error removing IQN iqn.1993-08.org.debian:01:387c4b432f1 from igroup ysaka-tri-iscsi-test: API status: failed, Reason: LUN maps for this initiator group exist, Code: 9029 (500 Internal Server Error)
command terminated with exit code 1

Moreover, I try to re-install Trindent v21.10.0 and it does not recover.

$ tridentctl uninstall -n trident
INFO Created Kubernetes clients.                   namespace=default version=v1.22.0
INFO Deleted Trident deployment.                  
INFO Deleted Trident daemonset.                   
INFO Deleted Trident service.                     
INFO Deleted Trident secret.                      
INFO Deleted cluster role binding.                
INFO Deleted cluster role.                        
INFO Deleted service account.                     
W1119 17:02:21.878025   54663 warnings.go:70] policy/v1beta1 PodSecurityPolicy is deprecated in v1.21+, unavailable in v1.25+
INFO Deleted pod security policy.                  podSecurityPolicy=tridentpods
INFO Deleted csidriver custom resource.            CSIDriver=csi.trident.netapp.io
INFO The uninstaller did not delete Trident's namespace in case it is going to be reused. 
INFO Trident uninstallation succeeded.            

$ kubectl get pod -n trident
No resources found in trident namespace.

$ tridentctl install -n trident
INFO Created Kubernetes clients.                   namespace=default version=v1.22.0
INFO Starting Trident installation.                namespace=trident
INFO Created service account.                     
INFO Created cluster role.                        
INFO Created cluster role binding.                
W1119 17:03:07.316885   55064 warnings.go:70] policy/v1beta1 PodSecurityPolicy is deprecated in v1.21+, unavailable in v1.25+
W1119 17:03:07.343480   55064 warnings.go:70] policy/v1beta1 PodSecurityPolicy is deprecated in v1.21+, unavailable in v1.25+
INFO Created Trident pod security policy.         
INFO Added finalizers to custom resource definitions. 
INFO Created Trident service.                     
INFO Created Trident secret.                      
INFO Created Trident deployment.                  
INFO Created Trident daemonset.                   
INFO Waiting for Trident pod to start.            
INFO Trident pod started.                          deployment=trident-csi namespace=trident pod=trident-csi-6d5dbdbf68-gg8z4
INFO Waiting for Trident REST interface.          

$ kubectl get pod -n trident
NAME                           READY   STATUS             RESTARTS      AGE
trident-csi-6d5dbdbf68-gg8z4   2/6     CrashLoopBackOff   8 (11s ago)   31s
trident-csi-bxrpj              1/2     Running            0             31s
trident-csi-msvgg              1/2     Running            0             31s
trident-csi-pc4lj              1/2     Running            0             31s
trident-csi-r4r2p              1/2     Running            0             31s
trident-csi-t6xmw              1/2     Running            0             31s
trident-csi-vz5qm              1/2     Running            0             31s
trident-csi-xhl5m              1/2     Running            0             31s

$ kubectl logs -f trident-csi-6d5dbdbf68-gg8z4 trident-main -n trident 
...
time="2021-11-19T08:03:10Z" level=info msg="Added an existing node." handler=Bootstrap node=demo-ysaka-tri-w-default-cda54bbb-wdmbz requestID=f7f0e743-db2c-4eaa-adbb-5e6cb9783b7a requestSource=Internal
time="2021-11-19T08:03:10Z" level=info msg="Initiator group (igroup) already exists." igroup=ysaka-tri-iscsi-test requestID=f7f0e743-db2c-4eaa-adbb-5e6cb9783b7a requestSource=Internal
time="2021-11-19T08:03:10Z" level=error msg="Trident initialization failed; error removing IQN iqn.1993-08.org.debian:01:387c4b432f1 from igroup ysaka-tri-iscsi-test: error removing IQN iqn.1993-08.org.debian:01:387c4b432f1 from igroup ysaka-tri-iscsi-test: API status: failed, Reason: LUN maps for this initiator group exist, Code: 9029"

So I need to delete any trident CR by manually before uninstalling trident. (I don't use trident delete backend command)
Then, I should install trident again.
As you may know, the recovery way is so denger. Any tridentvolume and tridentbackend resources were deleted.
So I should recover PVC/PV information using tridentctl import command.
I think it is not possible to do this every time a node event occurs.

ysakashita picture ysakashita on 19 Nov 2021

As discussed in https://github.com/NetApp/trident/issues/669#issue-1044449156 ,

I belive that 

        err = clientAPI.IgroupRemove(ctx, igroupName, iqn, false)

is wrong.
The ONTAP manual(lun igroup delete) states the following

You can specify the force option to delete an initiator group and remove existing LUN maps defined for that initiator group.

Therefore, I think the parameter must be set true.

ysakashita picture ysakashita on 19 Nov 2021

Hi @ysakashita,

Thank you for the detailed description of the problem. The team is currently working on a fix for this issue and we'll update this issue once a fix is merged.

gnarl picture gnarl on 19 Nov 2021
👍1

@gnarl Thank you for sharing current status. I hope the critical bug will be fixed ASAP.

ysakashita picture ysakashita on 20 Nov 2021

This is issue is fixed in commit 50cf71e and is included in the Trident 21.10.1 release.

gnarl picture gnarl on 17 Dec 2021
🎉1
Was this page helpful?
0 / 5 - 0 ratings

Related issues

r0ss3 picture r0ss3  ·  6Comments
arndt-netapp picture arndt-netapp  ·  6Comments
ffilippopoulos picture ffilippopoulos  ·  4Comments
uberspot picture uberspot  ·  3Comments
leemmcc picture leemmcc  ·  4Comments