CSINodeInfo should not be required

[xing-yang]

I updated my driver to support CSI v1.0.0 and tested it with K8S release-1.13 branch. I didn't enable CSINodeInfo feature gate. Attach volume failed with the following errors, indicating CSINodeInfo is required.

external-attacher logs:

I1121 17:45:21.698075 1 reflector.go:357] k8s.io/client-go/informers/factory.go:131: Watch close - *v1.Node total 45 items received
I1121 17:46:41.961154 1 controller.go:167] Started VA processing "csi-287954e86d0185d269332671ff365816b3506d826a6a01ca8c4caf4256d7a8b3"
I1121 17:46:41.961200 1 csi_handler.go:91] CSIHandler: processing VA "csi-287954e86d0185d269332671ff365816b3506d826a6a01ca8c4caf4256d7a8b3"
I1121 17:46:41.961214 1 csi_handler.go:118] Attaching "csi-287954e86d0185d269332671ff365816b3506d826a6a01ca8c4caf4256d7a8b3"
I1121 17:46:41.961224 1 csi_handler.go:257] Starting attach operation for "csi-287954e86d0185d269332671ff365816b3506d826a6a01ca8c4caf4256d7a8b3"
I1121 17:46:41.961355 1 csi_handler.go:212] PV finalizer is already set on "pvc-990567c7-edb3-11e8-a8c1-000c29e70439"
I1121 17:46:41.968744 1 csi_handler.go:516] Can't get CSINodeInfo 127.0.0.1: csinodeinfos.csi.storage.k8s.io "127.0.0.1" is forbidden: User "system:serviceaccount:default:csi-attacher" cannot get resource "csinodeinfos" in API group "csi.storage.k8s.io" at the cluster scope
I1121 17:46:41.968795 1 csi_handler.go:380] Saving attach error to "csi-287954e86d0185d269332671ff365816b3506d826a6a01ca8c4caf4256d7a8b3"
I1121 17:46:41.972135 1 csi_handler.go:390] Saved attach error to "csi-287954e86d0185d269332671ff365816b3506d826a6a01ca8c4caf4256d7a8b3"
I1121 17:46:41.972155 1 csi_handler.go:101] Error processing "csi-287954e86d0185d269332671ff365816b3506d826a6a01ca8c4caf4256d7a8b3": failed to attach: node "127.0.0.1" has no NodeID annotation
I1121 17:46:41.972177 1 controller.go:167] Started VA processing "csi-287954e86d0185d269332671ff365816b3506d826a6a01ca8c4caf4256d7a8b3"
I1121 17:46:41.972182 1 csi_handler.go:91] CSIHandler: processing VA "csi-287954e86d0185d269332671ff365816b3506d826a6a01ca8c4caf4256d7a8b3"
I1121 17:46:41.972186 1 csi_handler.go:118] Attaching "csi-287954e86d0185d269332671ff365816b3506d826a6a01ca8c4caf4256d7a8b3"
I1121 17:46:41.972190 1 csi_handler.go:257] Starting attach operation for "csi-287954e86d0185d269332671ff365816b3506d826a6a01ca8c4caf4256d7a8b3"
I1121 17:46:41.972231 1 csi_handler.go:212] PV finalizer is already set on "pvc-990567c7-edb3-11e8-a8c1-000c29e70439"
I1121 17:46:41.973221 1 csi_handler.go:516] Can't get CSINodeInfo 127.0.0.1: csinodeinfos.csi.storage.k8s.io "127.0.0.1" is forbidden: User "system:serviceaccount:default:csi-attacher" cannot get resource "csinodeinfos" in API group "csi.storage.k8s.io" at the cluster scope
I1121 17:46:41.973257 1 csi_handler.go:380] Saving attach error to "csi-287954e86d0185d269332671ff365816b3506d826a6a01ca8c4caf4256d7a8b3"
I1121 17:46:41.975052 1 csi_handler.go:390] Saved attach error to "csi-287954e86d0185d269332671ff365816b3506d826a6a01ca8c4caf4256d7a8b3"
I1121 17:46:41.975087 1 csi_handler.go:101] Error processing "csi-287954e86d0185d269332671ff365816b3506d826a6a01ca8c4caf4256d7a8b3": failed to attach: node "127.0.0.1" has no NodeID annotation

[pohly]

Xing Yang <notifications@github.com> writes:

I updated my driver to support CSI v1.0.0 and tested it with K8S release-1.13 branch. I didn't enable CSINodeInfo feature gate. Attach volume failed with the following errors, indicating CSINodeInfo is required. external-attacher logs: I1121 17:45:21.698075 1 reflector.go:357] k8s.io/client-go/informers/factory.go:131: Watch close - *v1.Node total 45 items received I1121 17:46:41.961154 1 controller.go:167] Started VA processing "csi-287954e86d0185d269332671ff365816b3506d826a6a01ca8c4caf4256d7a8b3" I1121 17:46:41.961200 1 csi_handler.go:91] CSIHandler: processing VA "csi-287954e86d0185d269332671ff365816b3506d826a6a01ca8c4caf4256d7a8b3" I1121 17:46:41.961214 1 csi_handler.go:118] Attaching "csi-287954e86d0185d269332671ff365816b3506d826a6a01ca8c4caf4256d7a8b3" I1121 17:46:41.961224 1 csi_handler.go:257] Starting attach operation for "csi-287954e86d0185d269332671ff365816b3506d826a6a01ca8c4caf4256d7a8b3" I1121 17:46:41.961355 1 csi_handler.go:212] PV finalizer is already set on "pvc-990567c7-edb3-11e8-a8c1-000c29e70439" I1121 17:46:41.968744 1 csi_handler.go:516] Can't get CSINodeInfo 127.0.0.1: csinodeinfos.csi.storage.k8s.io "127.0.0.1" is forbidden: User "system:serviceaccount:default:csi-attacher" cannot get resource "csinodeinfos" in API group "csi.storage.k8s.io" at the cluster scope

I might be mistaken, but I think CSINodeInfo is now beta in 1.13 and thus enabled by default. Your cluster deployment must create the CRDs and if it doesn't, they have to be created manually as in https://kubernetes-csi.github.io/docs/Example.html#deployment

I1121 17:46:41.968795 1 csi_handler.go:380] Saving attach error to "csi-287954e86d0185d269332671ff365816b3506d826a6a01ca8c4caf4256d7a8b3" I1121 17:46:41.972135 1 csi_handler.go:390] Saved attach error to "csi-287954e86d0185d269332671ff365816b3506d826a6a01ca8c4caf4256d7a8b3" I1121 17:46:41.972155 1 csi_handler.go:101] Error processing "csi-287954e86d0185d269332671ff365816b3506d826a6a01ca8c4caf4256d7a8b3": failed to attach: node "127.0.0.1" has no NodeID annotation I1121 17:46:41.972177 1 controller.go:167] Started VA processing "csi-287954e86d0185d269332671ff365816b3506d826a6a01ca8c4caf4256d7a8b3" I1121 17:46:41.972182 1 csi_handler.go:91] CSIHandler: processing VA "csi-287954e86d0185d269332671ff365816b3506d826a6a01ca8c4caf4256d7a8b3" I1121 17:46:41.972186 1 csi_handler.go:118] Attaching "csi-287954e86d0185d269332671ff365816b3506d826a6a01ca8c4caf4256d7a8b3" I1121 17:46:41.972190 1 csi_handler.go:257] Starting attach operation for "csi-287954e86d0185d269332671ff365816b3506d826a6a01ca8c4caf4256d7a8b3" I1121 17:46:41.972231 1 csi_handler.go:212] PV finalizer is already set on "pvc-990567c7-edb3-11e8-a8c1-000c29e70439" I1121 17:46:41.973221 1 csi_handler.go:516] Can't get CSINodeInfo 127.0.0.1: csinodeinfos.csi.storage.k8s.io "127.0.0.1" is forbidden: User "system:serviceaccount:default:csi-attacher" cannot get resource "csinodeinfos" in API group "csi.storage.k8s.io" at the cluster scope

What are you RBAC rules? The builtin roles are out-dated and must be replaced with the ones from the YAML files provided with the sidecar containers. Some modifications may be needed depending on how you use the sidecars. The example above is for 1.12, but I think the RBAC rules are still the same for 1.13.

[xing-yang]

CSINodeInfo is still Alpha in 1.13.

I tried to work around this problem by enabling the feature gates for CSINodeInfo and CSIDriverRegistry and I did follow the example here: https://kubernetes-csi.github.io/docs/Example.html#deployment

I still got the following errors in the external-attacher:

I1121 18:38:19.079423 1 csi_handler.go:91] CSIHandler: processing VA "csi-4800a666312223e9f2c660a5e3a07ba348ac2735a7533db59082418397ee0fff"
I1121 18:38:19.079429 1 csi_handler.go:118] Attaching "csi-4800a666312223e9f2c660a5e3a07ba348ac2735a7533db59082418397ee0fff"
I1121 18:38:19.079438 1 csi_handler.go:257] Starting attach operation for "csi-4800a666312223e9f2c660a5e3a07ba348ac2735a7533db59082418397ee0fff"
I1121 18:38:19.079497 1 csi_handler.go:212] PV finalizer is already set on "pvc-7e549db8-edbc-11e8-8278-000c29e70439"
I1121 18:38:19.083760 1 csi_handler.go:516] Can't get CSINodeInfo 127.0.0.1: csinodeinfos.csi.storage.k8s.io "127.0.0.1" not found
I1121 18:38:19.083782 1 csi_handler.go:380] Saving attach error to "csi-4800a666312223e9f2c660a5e3a07ba348ac2735a7533db59082418397ee0fff"
I1121 18:38:19.086711 1 csi_handler.go:390] Saved attach error to "csi-4800a666312223e9f2c660a5e3a07ba348ac2735a7533db59082418397ee0fff"
I1121 18:38:19.086730 1 csi_handler.go:101] Error processing "csi-4800a666312223e9f2c660a5e3a07ba348ac2735a7533db59082418397ee0fff": failed to attach: node "127.0.0.1" has no NodeID annotation

The "forbidden" error message was gone, but it still couldn't find CSINodeInfo.

There was also this message in kubelet:

I1123 10:17:57.603669 59338 reflector.go:169] Listing and watching *v1alpha1.CSIDriver from k8s.io/csi-api/pkg/client/informers/externalversions/factory.go:117
E1123 10:17:57.605228 59338 reflector.go:134] k8s.io/csi-api/pkg/client/informers/externalversions/factory.go:117: Failed to list *v1alpha1.CSIDriver: the server could not find the requested resource (get csidrivers.csi.storage.k8s.io)
E1123 10:17:57.609073 59338 kubele

[xing-yang]

I have a temporary fix for this problem: #100
With this fix, my CSI plugin works now.

Note that when testing with hostpath CSI plugin, I didn't run into this problem because hostpath didn't implement ControllerPublishVolume and therefore it uses the trivial_handler rather than the csi_handler in external-attacher.

[jsafrane]

I checked today with 1.0-canary images of everything, CSINodeInfo is not required in 1.13 at all.

In attacher logs I still can see an error about CSINodeInfo, but attacher continues without it:

I1126 12:46:11.804570       1 csi_handler.go:118] Attaching "csi-6eec4ae2b83d654c234b32dcfd7e2785508d30da7ccba0b75f101b02c42dceeb"
I1126 12:46:11.804592       1 csi_handler.go:257] Starting attach operation for "csi-6eec4ae2b83d654c234b32dcfd7e2785508d30da7ccba0b75f101b02c42dceeb"
I1126 12:46:11.804694       1 csi_handler.go:218] Adding finalizer to PV "pvc-002a4e5f-f179-11e8-adb4-5254000472e3"
I1126 12:46:11.820575       1 csi_handler.go:226] PV finalizer added to "pvc-002a4e5f-f179-11e8-adb4-5254000472e3"
I1126 12:46:11.820619       1 controller.go:197] Started PV processing "pvc-002a4e5f-f179-11e8-adb4-5254000472e3"
I1126 12:46:11.820642       1 csi_handler.go:410] CSIHandler: processing PV "pvc-002a4e5f-f179-11e8-adb4-5254000472e3"
I1126 12:46:11.820667       1 csi_handler.go:414] CSIHandler: processing PV "pvc-002a4e5f-f179-11e8-adb4-5254000472e3": no deletion timestamp, ignoring
I1126 12:46:11.821583       1 csi_handler.go:516] Can't get CSINodeInfo 127.0.0.1: csinodeinfos.csi.storage.k8s.io "127.0.0.1" is forbidden: User "system:serviceaccount:default:csi-service-account" cannot get resource "csinodeinfos" in API group "csi.storage.k8s.io" at the cluster scope
I1126 12:46:11.821666       1 csi_handler.go:179] VA finalizer added to "csi-6eec4ae2b83d654c234b32dcfd7e2785508d30da7ccba0b75f101b02c42dceeb"
I1126 12:46:11.821689       1 csi_handler.go:193] NodeID annotation added to "csi-6eec4ae2b83d654c234b32dcfd7e2785508d30da7ccba0b75f101b02c42dceeb"
I1126 12:46:11.825572       1 csi_handler.go:203] VolumeAttachment "csi-6eec4ae2b83d654c234b32dcfd7e2785508d30da7ccba0b75f101b02c42dceeb" updated with finalizer and/or NodeID annotation
I1126 12:46:11.825632       1 connection.go:235] GRPC call: /csi.v1.Controller/ControllerPublishVolume
I1126 12:46:11.825645       1 connection.go:236] GRPC request: volume_id:"4" node_id:"io.kubernetes.storage.mock" volume_capability:<mount:<fs_type:"ext4" > access_mode:<mode:SINGLE_NODE_WRITER > > volume_context:<key:"name" value:"pvc-002a4e5f-f179-11e8-adb4-5254000472e3" > volume_context:<key:"storage.kubernetes.io/csiProvisionerIdentity" value:"1543236260925-8081-io.kubernetes.storage.mock" > 
I1126 12:46:11.826582       1 connection.go:238] GRPC response: publish_context:<key:"device" value:"/dev/mock" > publish_context:<key:"readonly" value:"false" > 
I1126 12:46:11.826632       1 connection.go:239] GRPC error: <nil>
I1126 12:46:11.826646       1 csi_handler.go:131] Attached "csi-6eec4ae2b83d654c234b32dcfd7e2785508d30da7ccba0b75f101b02c42dceeb"
I1126 12:46:11.826665       1 util.go:33] Marking as attached "csi-6eec4ae2b83d654c234b32dcfd7e2785508d30da7ccba0b75f101b02c42dceeb"
I1126 12:46:11.829693       1 util.go:43] Marked as attached "csi-6eec4ae2b83d654c234b32dcfd7e2785508d30da7ccba0b75f101b02c42dceeb"
I1126 12:46:11.829717       1 csi_handler.go:137] Fully attached "csi-6eec4ae2b83d654c234b32dcfd7e2785508d30da7ccba0b75f101b02c42dceeb"

In your case, the root cause is node "127.0.0.1" has no NodeID annotation. Many things changed in 1.0, in my case I had to change yaml of my driver to use /var/lib/kubelet/plugins_registry/ instead of /var/lib/kubelet/plugins for driver registrar socket directory, something like this:

kubernetes-sigs/gcp-compute-persistent-disk-csi-driver@762870b

But there may be more reasons why the node does not have annotation. Check driver-registrar and kubelet logs.

[xing-yang]

Thanks @jsafrane ! I'll re-test with the new driver registrar path. I remember there is a change but couldn't find the relevant PR about it.

[xing-yang]

I modified the driver registrar socket directory and tested without CSINodeInfo (using external-attacher v1.0.0 image and driver-registrar v1.0-canary), but I got the same errors in the attacher. Here are errors in kube-controller-manager.log:

E1126 07:42:05.000173 2970 csi_attacher.go:228] kubernetes.io/csi: attachment for 26b93b42-d7ad-4d04-a217-e0ff38f4b348 failed: node "127.0.0.1" has no NodeID annotation
E1126 07:42:05.000243 2970 nestedpendingoperations.go:267] Operation for ""kubernetes.io/csi/csi-opensdsplugin^26b93b42-d7ad-4d04-a217-e0ff38f4b348"" failed. No retries permitted until 2018-11-26 07:42:05.500224109 -0800 PST m=+709.906687860 (durationBeforeRetry 500ms). Error: "AttachVolume.Attach failed for volume "pvc-c82060d8-f191-11e8-8ce4-000c29e70439" (UniqueName: "kubernetes.io/csi/csi-opensdsplugin^26b93b42-d7ad-4d04-a217-e0ff38f4b348") from node "127.0.0.1" : node "127.0.0.1" has no NodeID annotation"

Driver registrar logs look fine:

kubectl logs csi-nodeplugin-opensdsplugin-xcf9z driver-registrar

I1126 15:39:16.423783 1 main.go:138] Version: v1.0.1-0-g78b5c12e
I1126 15:39:16.423841 1 main.go:145] Attempting to open a gRPC connection with: "/csi/csi.sock"
I1126 15:39:16.423854 1 connection.go:68] Connecting to /csi/csi.sock
I1126 15:39:16.423982 1 connection.go:95] Still trying, connection is CONNECTING
I1126 15:39:16.424090 1 connection.go:95] Still trying, connection is TRANSIENT_FAILURE
I1126 15:39:17.424620 1 connection.go:92] Connected
I1126 15:39:17.424637 1 main.go:153] Calling CSI driver to discover driver name.
I1126 15:39:17.424645 1 connection.go:136] GRPC call: /csi.v1.Identity/GetPluginInfo
I1126 15:39:17.424649 1 connection.go:137] GRPC request:
I1126 15:39:17.425406 1 connection.go:139] GRPC response: name:"csi-opensdsplugin"
I1126 15:39:17.425453 1 connection.go:140] GRPC error:
I1126 15:39:17.425459 1 main.go:161] CSI driver name: "csi-opensdsplugin"
I1126 15:39:17.425464 1 main.go:165] Loading kubeconfig.
I1126 15:39:17.425711 1 node_register.go:55] Calling CSI driver to discover node ID.
I1126 15:39:17.426025 1 connection.go:136] GRPC call: /csi.v1.Node/NodeGetInfo
I1126 15:39:17.426050 1 connection.go:137] GRPC request:
I1126 15:39:17.430834 1 connection.go:139] GRPC response: node_id:"ubuntu,iqn:iqn.1993-08.org.debian:01:c6961059376e"
I1126 15:39:17.430961 1 connection.go:140] GRPC error:
I1126 15:39:17.430972 1 node_register.go:63] CSI driver node ID: "ubuntu,iqn:iqn.1993-08.org.debian:01:c6961059376e"
I1126 15:39:17.431251 1 node_register.go:86] Starting Registration Server at: /registration/csi-opensdsplugin-reg.sock
I1126 15:39:17.432065 1 node_register.go:93] Registration Server started at: /registration/csi-opensdsplugin-reg.sock

[xing-yang]

Verified PR #101 fixed this issue. Thanks @jsafrane !

[hadifarnoud]

if CSINodeInfo is not required, please remove it from docs