Debug why some /csi.v1.Node methods are not called

[YiannisGkoufas]

Hi! I was working on our CSI S3 implementation ( https://github.com/IBM/dataset-lifecycle-framework/tree/master/src/csi-s3 ) and have successfully tested it multiple environments of k8s 1.16+ without a problem. However, in a recent deployment I have been getting some issues about the attacher not being called.

Specifically, in a working setting I was seeing logs like this:

I1022 14:47:03.515918       1 utils.go:97] GRPC call: /csi.v1.Controller/CreateVolume
I1022 14:47:03.516230       1 utils.go:98] GRPC request: {"capacity_range":{"required_bytes":5368709120},"name":"pvc-5ae4381e-8cc0-48cd-864f-a741f91fdc8d","parameters":{"mounter":"goofys"},"secrets":"***stripped***","volume_capabilities":[{"AccessType":{"Mount":{}},"access_mode":{"mode":5}}]}
I1022 14:47:03.520123       1 controllerserver.go:59] Got a request to create volume pvc-5ae4381e-8cc0-48cd-864f-a741f91fdc8d
I1022 14:47:04.585273       1 controllerserver.go:88] create volume pvc-5ae4381e-8cc0-48cd-864f-a741f91fdc8d
I1022 14:47:04.585541       1 utils.go:103] GRPC response: {"volume":{"capacity_bytes":10000000000000,"volume_context":{"mounter":"goofys"},"volume_id":"pvc-5ae4381e-8cc0-48cd-864f-a741f91fdc8d"}}
I1022 14:47:23.282358       1 utils.go:97] GRPC call: /csi.v1.Node/NodeGetCapabilities
I1022 14:47:23.282392       1 utils.go:98] GRPC request: {}
I1022 14:47:23.283316       1 utils.go:103] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}}]}
I1022 14:47:23.297263       1 utils.go:97] GRPC call: /csi.v1.Node/NodeStageVolume
I1022 14:47:23.297292       1 utils.go:98] GRPC request: {"secrets":"***stripped***","staging_target_path":"/var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-5ae4381e-8cc0-48cd-864f-a741f91fdc8d/globalmount","volume_capability":{"AccessType":{"Mount":{}},"access_mode":{"mode":5}},"volume_context":{"mounter":"goofys","storage.kubernetes.io/csiProvisionerIdentity":"1603377947105-8081-ch.ctrox.csi.s3-driver"},"volume_id":"pvc-5ae4381e-8cc0-48cd-864f-a741f91fdc8d"}
I1022 14:47:23.298971       1 utils.go:103] GRPC response: {}
I1022 14:47:23.306173       1 utils.go:97] GRPC call: /csi.v1.Node/NodeGetCapabilities
I1022 14:47:23.306211       1 utils.go:98] GRPC request: {}
I1022 14:47:23.306726       1 utils.go:103] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}}]}
I1022 14:47:23.318664       1 utils.go:97] GRPC call: /csi.v1.Node/NodePublishVolume
I1022 14:47:23.318695       1 utils.go:98] GRPC request: {"secrets":"***stripped***","staging_target_path":"/var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-5ae4381e-8cc0-48cd-864f-a741f91fdc8d/globalmount","target_path":"/var/lib/kubelet/pods/289430f2-cff7-4382-bc15-d947385f5197/volumes/kubernetes.io~csi/pvc-5ae4381e-8cc0-48cd-864f-a741f91fdc8d/mount","volume_capability":{"AccessType":{"Mount":{}},"access_mode":{"mode":5}},"volume_context":{"mounter":"goofys","storage.kubernetes.io/csiProvisionerIdentity":"1603377947105-8081-ch.ctrox.csi.s3-driver"},"volume_id":"pvc-5ae4381e-8cc0-48cd-864f-a741f91fdc8d"}
I1022 14:47:23.320385       1 nodeserver.go:77] target /var/lib/kubelet/pods/289430f2-cff7-4382-bc15-d947385f5197/volumes/kubernetes.io~csi/pvc-5ae4381e-8cc0-48cd-864f-a741f91fdc8d/mount

In the non-working case the logs stop on:

I1022 15:24:39.874091       1 utils.go:103] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}}]}
I1022 15:26:44.082754       1 utils.go:97] GRPC call: /csi.v1.Controller/CreateVolume
I1022 15:26:44.082787       1 utils.go:98] GRPC request: {"capacity_range":{"required_bytes":5368709120},"name":"pvc-816b6ed1-c2b1-46a2-9089-c3b38a838699","parameters":{"mounter":"goofys"},"secrets":"***stripped***","volume_capabilities":[{"AccessType":{"Mount":{}},"access_mode":{"mode":5}}]}
I1022 15:26:44.085223       1 controllerserver.go:59] Got a request to create volume pvc-816b6ed1-c2b1-46a2-9089-c3b38a838699
I1022 15:26:45.137443       1 controllerserver.go:88] create volume pvc-816b6ed1-c2b1-46a2-9089-c3b38a838699
I1022 15:26:45.137731       1 utils.go:103] GRPC response: {"volume":{"capacity_bytes":10000000000000,"volume_context":{"mounter":"goofys"},"volume_id":"pvc-816b6ed1-c2b1-46a2-9089-c3b38a838699"}}

This means that the methods /csi.v1.Node/NodeGetCapabilities /csi.v1.Node/NodeStageVolume etc are not called and I am not sure how to debug this. I suspect that this might have to do with the socket connection but I don't know of a way to verify that.

Any help would be highly appreciated!

[gnufied]

Please open this in kubernetes/kubernetes repo

[YiannisGkoufas]

Sure!