Repositories not mounting

Question

Repositories not mounting

Closed this issue 2 years ago · 5 comments

I've been trying to upgrade to cvmfs-csi v2 and get it working with the galaxyproject repos but listing the cvmfs repo folder shows nothing. A slight delay can be seen, indicating that maybe autofs is trying to mount the folder.

I then backtracked and tried to recreate the basic deployment examples by following the instructions here: https://github.com/cvmfs-contrib/cvmfs-csi/blob/master/docs/deploying.md and here: https://github.com/cvmfs-contrib/cvmfs-csi/blob/master/docs/how-to-use.md. Same issue.

If I exec into the cvmfs-demo pod and exec ls -l /my-cvmfs/atlas.cern.ch I can see an additional delay, but then it just errors out with file or directory not found. I didn't see anything of note in the csi pod logs. I wasn't quite sure how to get to the autofs logs.

Would appreciate some insights into how to debug this issue.

Environment:
Provider: RKE2
Kubernetes Version: v1.24.4
DISTRIB_ID=Ubuntu
DISTRIB_RELEASE=20.04
DISTRIB_CODENAME=focal
DISTRIB_DESCRIPTION="Ubuntu 20.04.2 LTS

node plugin logs:

Sun, Dec 11 2022 11:37:56 am | I1211 06:07:56.403738 482051 main.go:92] Running CVMFS CSI plugin with [/csi-cvmfsplugin -v=5 --nodeid=ip-10-0-35-178.ec2.internal --endpoint=unix:///var/lib/kubelet/plugins/cvmfs.csi.cern.ch/csi.sock --drivername=cvmfs.csi.cern.ch --start-automount-daemon=true --role=identity,node]
Sun, Dec 11 2022 11:37:56 am | I1211 06:07:56.403824 482051 driver.go:139] Driver: cvmfs.csi.cern.ch
Sun, Dec 11 2022 11:37:56 am | I1211 06:07:56.403833 482051 driver.go:141] Version: v2.0.0 (commit: 1e30ea639263f74179f971aea1cfad170a6b5c89; build time: 2022-12-11 06:07:56.402341425 +0000 UTC m=+0.002192591; metadata: )
Sun, Dec 11 2022 11:37:56 am | I1211 06:07:56.403860 482051 driver.go:155] Registering Identity server
Sun, Dec 11 2022 11:37:56 am | I1211 06:07:56.403939 482051 driver.go:210] Exec-ID 1: Running command env=[] prog=/usr/bin/cvmfs2 args=[cvmfs2 --version]
Sun, Dec 11 2022 11:37:56 am | I1211 06:07:56.407309 482051 driver.go:210] Exec-ID 1: Process exited: exit status 0
Sun, Dec 11 2022 11:37:56 am | I1211 06:07:56.407333 482051 driver.go:170] CernVM-FS version 2.9.4
Sun, Dec 11 2022 11:37:56 am | I1211 06:07:56.407360 482051 driver.go:227] Exec-ID 2: Running command env=[] prog=/usr/bin/cvmfs_config args=[cvmfs_config setup]
Sun, Dec 11 2022 11:37:57 am | I1211 06:07:57.982777 482051 driver.go:227] Exec-ID 2: Process exited: exit status 0
Sun, Dec 11 2022 11:37:57 am | I1211 06:07:57.982831 482051 driver.go:233] Exec-ID 3: Running command env=[] prog=/usr/sbin/automount args=[automount]
Sun, Dec 11 2022 11:37:58 am | I1211 06:07:58.001347 482051 driver.go:233] Exec-ID 3: Process exited: exit status 0
Sun, Dec 11 2022 11:37:58 am | I1211 06:07:58.001409 482051 driver.go:240] Exec-ID 4: Running command env=[] prog=/usr/bin/mount args=[mount --make-shared /cvmfs]
Sun, Dec 11 2022 11:37:58 am | I1211 06:07:58.002743 482051 driver.go:240] Exec-ID 4: Process exited: exit status 0
Sun, Dec 11 2022 11:37:58 am | I1211 06:07:58.002760 482051 driver.go:187] Registering Node server with capabilities []
Sun, Dec 11 2022 11:37:58 am | I1211 06:07:58.002900 482051 grpcserver.go:106] Listening for connections on /var/lib/kubelet/plugins/cvmfs.csi.cern.ch/csi.sock
Sun, Dec 11 2022 11:37:58 am | I1211 06:07:58.408741 482051 grpcserver.go:136] Call-ID 1: Call: /csi.v1.Identity/GetPluginInfo
Sun, Dec 11 2022 11:37:58 am | I1211 06:07:58.410334 482051 grpcserver.go:137] Call-ID 1: Request: {}
Sun, Dec 11 2022 11:37:58 am | I1211 06:07:58.410419 482051 grpcserver.go:143] Call-ID 1: Response: {"name":"cvmfs.csi.cern.ch","vendor_version":"v2.0.0"}
Sun, Dec 11 2022 11:37:58 am | I1211 06:07:58.707310 482051 grpcserver.go:136] Call-ID 2: Call: /csi.v1.Node/NodeGetInfo
Sun, Dec 11 2022 11:37:58 am | I1211 06:07:58.707353 482051 grpcserver.go:137] Call-ID 2: Request: {}
Sun, Dec 11 2022 11:37:58 am | I1211 06:07:58.707445 482051 grpcserver.go:143] Call-ID 2: Response: {"node_id":"ip-10-0-35-178.ec2.internal"}
Sun, Dec 11 2022 11:38:08 am | I1211 06:08:08.440837 482051 grpcserver.go:136] Call-ID 3: Call: /csi.v1.Node/NodeUnpublishVolume
Sun, Dec 11 2022 11:38:08 am | I1211 06:08:08.440918 482051 grpcserver.go:137] Call-ID 3: Request: {"target_path":"/var/lib/kubelet/pods/03a7dca9-87d7-4085-9871-88bda5597ab6/volumes/kubernetes.io~csi/pvc-ae299e01-0ec5-4925-a2bf-b440eb423aef/mount","volume_id":"pvc-ae299e01-0ec5-4925-a2bf-b440eb423aef"}
Sun, Dec 11 2022 11:38:08 am | I1211 06:08:08.440982 482051 mountutil.go:99] Exec-ID 5: Running command env=[] prog=/usr/bin/umount args=[umount --recursive /var/lib/kubelet/pods/03a7dca9-87d7-4085-9871-88bda5597ab6/volumes/kubernetes.io~csi/pvc-ae299e01-0ec5-4925-a2bf-b440eb423aef/mount]
Sun, Dec 11 2022 11:38:08 am | I1211 06:08:08.448234 482051 mountutil.go:99] Exec-ID 5: Process exited: exit status 0
Sun, Dec 11 2022 11:38:08 am | I1211 06:08:08.448356 482051 grpcserver.go:143] Call-ID 3: Response: {}
Sun, Dec 11 2022 11:38:08 am | I1211 06:08:08.555011 482051 grpcserver.go:136] Call-ID 4: Call: /csi.v1.Node/NodeGetCapabilities
Sun, Dec 11 2022 11:38:08 am | I1211 06:08:08.555049 482051 grpcserver.go:137] Call-ID 4: Request: {}
Sun, Dec 11 2022 11:38:08 am | I1211 06:08:08.555138 482051 grpcserver.go:143] Call-ID 4: Response: {}
Sun, Dec 11 2022 11:38:17 am | I1211 06:08:17.355531 482051 grpcserver.go:136] Call-ID 5: Call: /csi.v1.Node/NodeUnpublishVolume
Sun, Dec 11 2022 11:38:17 am | I1211 06:08:17.355589 482051 grpcserver.go:137] Call-ID 5: Request: {"target_path":"/var/lib/kubelet/pods/25145b26-8019-4ce4-9195-c50dc0d69035/volumes/kubernetes.io~csi/pvc-486c1c4b-0be4-4fbe-983d-32a245b731b5/mount","volume_id":"pvc-486c1c4b-0be4-4fbe-983d-32a245b731b5"}
Sun, Dec 11 2022 11:38:17 am | I1211 06:08:17.355645 482051 mountutil.go:99] Exec-ID 6: Running command env=[] prog=/usr/bin/umount args=[umount --recursive /var/lib/kubelet/pods/25145b26-8019-4ce4-9195-c50dc0d69035/volumes/kubernetes.io~csi/pvc-486c1c4b-0be4-4fbe-983d-32a245b731b5/mount]
Sun, Dec 11 2022 11:38:17 am | I1211 06:08:17.359151 482051 mountutil.go:99] Exec-ID 6: Process exited: exit status 0
Sun, Dec 11 2022 11:38:17 am | I1211 06:08:17.359227 482051 grpcserver.go:143] Call-ID 5: Response: {}
Sun, Dec 11 2022 11:38:18 am | I1211 06:08:18.675670 482051 grpcserver.go:136] Call-ID 6: Call: /csi.v1.Node/NodeUnpublishVolume
Sun, Dec 11 2022 11:38:18 am | I1211 06:08:18.675743 482051 grpcserver.go:136] Call-ID 7: Call: /csi.v1.Node/NodeUnpublishVolume
Sun, Dec 11 2022 11:38:18 am | I1211 06:08:18.675741 482051 grpcserver.go:137] Call-ID 6: Request: {"target_path":"/var/lib/kubelet/pods/7d15c20f-5d95-4b82-a2d4-fdb518d40f1f/volumes/kubernetes.io~csi/pvc-486c1c4b-0be4-4fbe-983d-32a245b731b5/mount","volume_id":"pvc-486c1c4b-0be4-4fbe-983d-32a245b731b5"}
Sun, Dec 11 2022 11:38:18 am | I1211 06:08:18.675818 482051 mountutil.go:99] Exec-ID 7: Running command env=[] prog=/usr/bin/umount args=[umount --recursive /var/lib/kubelet/pods/7d15c20f-5d95-4b82-a2d4-fdb518d40f1f/volumes/kubernetes.io~csi/pvc-486c1c4b-0be4-4fbe-983d-32a245b731b5/mount]
Sun, Dec 11 2022 11:38:18 am | I1211 06:08:18.675802 482051 grpcserver.go:137] Call-ID 7: Request: {"target_path":"/var/lib/kubelet/pods/b483ac10-c6e3-444d-96f0-3bd3ec9e0e8b/volumes/kubernetes.io~csi/pvc-486c1c4b-0be4-4fbe-983d-32a245b731b5/mount","volume_id":"pvc-486c1c4b-0be4-4fbe-983d-32a245b731b5"}
Sun, Dec 11 2022 11:38:18 am | I1211 06:08:18.675922 482051 mountutil.go:99] Exec-ID 8: Running command env=[] prog=/usr/bin/umount args=[umount --recursive /var/lib/kubelet/pods/b483ac10-c6e3-444d-96f0-3bd3ec9e0e8b/volumes/kubernetes.io~csi/pvc-486c1c4b-0be4-4fbe-983d-32a245b731b5/mount]
Sun, Dec 11 2022 11:38:18 am | I1211 06:08:18.675945 482051 grpcserver.go:136] Call-ID 9: Call: /csi.v1.Node/NodeUnpublishVolume
Sun, Dec 11 2022 11:38:18 am | I1211 06:08:18.675962 482051 grpcserver.go:136] Call-ID 10: Call: /csi.v1.Node/NodeUnpublishVolume
Sun, Dec 11 2022 11:38:18 am | I1211 06:08:18.675999 482051 grpcserver.go:137] Call-ID 9: Request: {"target_path":"/var/lib/kubelet/pods/b3e59a3a-12db-48bb-afdc-7c106d1de576/volumes/kubernetes.io~csi/pvc-486c1c4b-0be4-4fbe-983d-32a245b731b5/mount","volume_id":"pvc-486c1c4b-0be4-4fbe-983d-32a245b731b5"}
Sun, Dec 11 2022 11:38:18 am | I1211 06:08:18.676007 482051 grpcserver.go:137] Call-ID 10: Request: {"target_path":"/var/lib/kubelet/pods/d5679f5d-8ff2-41d2-8869-e36e81e7f6da/volumes/kubernetes.io~csi/pvc-486c1c4b-0be4-4fbe-983d-32a245b731b5/mount","volume_id":"pvc-486c1c4b-0be4-4fbe-983d-32a245b731b5"}
Sun, Dec 11 2022 11:38:18 am | I1211 06:08:18.675920 482051 grpcserver.go:136] Call-ID 8: Call: /csi.v1.Node/NodeUnpublishVolume
Sun, Dec 11 2022 11:38:18 am | I1211 06:08:18.676044 482051 mountutil.go:99] Exec-ID 9: Running command env=[] prog=/usr/bin/umount args=[umount --recursive /var/lib/kubelet/pods/d5679f5d-8ff2-41d2-8869-e36e81e7f6da/volumes/kubernetes.io~csi/pvc-486c1c4b-0be4-4fbe-983d-32a245b731b5/mount]
Sun, Dec 11 2022 11:38:18 am | I1211 06:08:18.676049 482051 mountutil.go:99] Exec-ID 10: Running command env=[] prog=/usr/bin/umount args=[umount --recursive /var/lib/kubelet/pods/b3e59a3a-12db-48bb-afdc-7c106d1de576/volumes/kubernetes.io~csi/pvc-486c1c4b-0be4-4fbe-983d-32a245b731b5/mount]
Sun, Dec 11 2022 11:38:18 am | I1211 06:08:18.676112 482051 grpcserver.go:137] Call-ID 8: Request: {"target_path":"/var/lib/kubelet/pods/3863a604-5200-4648-bf81-ae82cfa168eb/volumes/kubernetes.io~csi/pvc-486c1c4b-0be4-4fbe-983d-32a245b731b5/mount","volume_id":"pvc-486c1c4b-0be4-4fbe-983d-32a245b731b5"}
Sun, Dec 11 2022 11:38:18 am | I1211 06:08:18.676157 482051 mountutil.go:99] Exec-ID 11: Running command env=[] prog=/usr/bin/umount args=[umount --recursive /var/lib/kubelet/pods/3863a604-5200-4648-bf81-ae82cfa168eb/volumes/kubernetes.io~csi/pvc-486c1c4b-0be4-4fbe-983d-32a245b731b5/mount]
Sun, Dec 11 2022 11:38:18 am | I1211 06:08:18.679577 482051 mountutil.go:99] Exec-ID 9: Process exited: exit status 0
Sun, Dec 11 2022 11:38:18 am | I1211 06:08:18.679660 482051 grpcserver.go:143] Call-ID 10: Response: {}
Sun, Dec 11 2022 11:38:18 am | I1211 06:08:18.680455 482051 mountutil.go:99] Exec-ID 7: Process exited: exit status 0
Sun, Dec 11 2022 11:38:18 am | I1211 06:08:18.680514 482051 grpcserver.go:143] Call-ID 6: Response: {}
Sun, Dec 11 2022 11:38:18 am | I1211 06:08:18.680709 482051 mountutil.go:99] Exec-ID 8: Process exited: exit status 0
Sun, Dec 11 2022 11:38:18 am | I1211 06:08:18.680787 482051 grpcserver.go:143] Call-ID 7: Response: {}
Sun, Dec 11 2022 11:38:18 am | I1211 06:08:18.687334 482051 mountutil.go:99] Exec-ID 10: Process exited: exit status 0
Sun, Dec 11 2022 11:38:18 am | I1211 06:08:18.687382 482051 mountutil.go:99] Exec-ID 11: Process exited: exit status 0
Sun, Dec 11 2022 11:38:18 am | I1211 06:08:18.687442 482051 grpcserver.go:143] Call-ID 9: Response: {}
Sun, Dec 11 2022 11:38:18 am | I1211 06:08:18.687470 482051 grpcserver.go:143] Call-ID 8: Response: {}
Sun, Dec 11 2022 11:38:18 am | I1211 06:08:18.780016 482051 grpcserver.go:136] Call-ID 11: Call: /csi.v1.Node/NodeGetCapabilities
Sun, Dec 11 2022 11:38:18 am | I1211 06:08:18.780087 482051 grpcserver.go:137] Call-ID 11: Request: {}
Sun, Dec 11 2022 11:38:18 am | I1211 06:08:18.780109 482051 grpcserver.go:143] Call-ID 11: Response: {}
Sun, Dec 11 2022 11:41:24 am | I1211 06:11:24.342514 482051 grpcserver.go:136] Call-ID 12: Call: /csi.v1.Node/NodeGetCapabilities
Sun, Dec 11 2022 11:41:24 am | I1211 06:11:24.342568 482051 grpcserver.go:137] Call-ID 12: Request: {}
Sun, Dec 11 2022 11:41:24 am | I1211 06:11:24.342585 482051 grpcserver.go:143] Call-ID 12: Response: {}
Sun, Dec 11 2022 11:41:24 am | I1211 06:11:24.343382 482051 grpcserver.go:136] Call-ID 13: Call: /csi.v1.Node/NodeGetCapabilities
Sun, Dec 11 2022 11:41:24 am | I1211 06:11:24.343428 482051 grpcserver.go:137] Call-ID 13: Request: {}
Sun, Dec 11 2022 11:41:24 am | I1211 06:11:24.343445 482051 grpcserver.go:143] Call-ID 13: Response: {}
Sun, Dec 11 2022 11:41:24 am | I1211 06:11:24.344110 482051 grpcserver.go:136] Call-ID 14: Call: /csi.v1.Node/NodeGetCapabilities
Sun, Dec 11 2022 11:41:24 am | I1211 06:11:24.344155 482051 grpcserver.go:137] Call-ID 14: Request: {}
Sun, Dec 11 2022 11:41:24 am | I1211 06:11:24.344173 482051 grpcserver.go:143] Call-ID 14: Response: {}
Sun, Dec 11 2022 11:41:24 am | I1211 06:11:24.344765 482051 grpcserver.go:136] Call-ID 15: Call: /csi.v1.Node/NodeGetCapabilities
Sun, Dec 11 2022 11:41:24 am | I1211 06:11:24.344804 482051 grpcserver.go:137] Call-ID 15: Request: {}
Sun, Dec 11 2022 11:41:24 am | I1211 06:11:24.344818 482051 grpcserver.go:143] Call-ID 15: Response: {}
Sun, Dec 11 2022 11:41:24 am | I1211 06:11:24.345580 482051 grpcserver.go:136] Call-ID 16: Call: /csi.v1.Node/NodePublishVolume
Sun, Dec 11 2022 11:41:24 am | I1211 06:11:24.345744 482051 grpcserver.go:137] Call-ID 16: Request: {"target_path":"/var/lib/kubelet/pods/110e7ec0-1c52-4bfe-b8f6-871d0b768115/volumes/kubernetes.io~csi/pvc-b08b6c81-c533-40a6-b29e-3a68016977a5/mount","volume_capability":{"AccessType":{"Mount":{}},"access_mode":{"mode":3}},"volume_context":{"storage.kubernetes.io/csiProvisionerIdentity":"1670738877264-8081-cvmfs.csi.cern.ch"},"volume_id":"pvc-b08b6c81-c533-40a6-b29e-3a68016977a5"}
Sun, Dec 11 2022 11:41:24 am | I1211 06:11:24.346563 482051 mountutil.go:75] Exec-ID 12: Running command env=[] prog=/usr/bin/mount args=[mount /cvmfs /var/lib/kubelet/pods/110e7ec0-1c52-4bfe-b8f6-871d0b768115/volumes/kubernetes.io~csi/pvc-b08b6c81-c533-40a6-b29e-3a68016977a5/mount --rbind --make-slave]
Sun, Dec 11 2022 11:41:24 am | I1211 06:11:24.348105 482051 mountutil.go:75] Exec-ID 12: Process exited: exit status 0
Sun, Dec 11 2022 11:41:24 am | I1211 06:11:24.348169 482051 grpcserver.go:143] Call-ID 16: Response: {}
Sun, Dec 11 2022 11:41:27 am | I1211 06:11:27.056814 482051 grpcserver.go:136] Call-ID 17: Call: /csi.v1.Node/NodeGetCapabilities
Sun, Dec 11 2022 11:41:27 am | I1211 06:11:27.056860 482051 grpcserver.go:137] Call-ID 17: Request: {}
Sun, Dec 11 2022 11:41:27 am | I1211 06:11:27.056875 482051 grpcserver.go:143] Call-ID 17: Response: {}
Sun, Dec 11 2022 11:42:41 am | I1211 06:12:41.003951 482051 grpcserver.go:136] Call-ID 18: Call: /csi.v1.Node/NodeGetCapabilities

Answer 1 · 2022-12-12T10:18:59.000Z

Hi @nuwang. The autofs logs are not there yet at the moment unfortunately, but we do have a PR for that #50.

Could you try exec-ing into a cvmfs-csi node plugin Pod, running mount -t cvmfs atlas.cern.ch /mnt -v and sending the output from that?

It's most likely an issue with client configuration. Can you share output of kubectl get cm -l app=cvmfs-csi -o yaml?

Answer 2 · 2022-12-12T11:57:37.000Z

@gman0 Thanks for the pointers.

[root@cvmfs-cvmfs-csi-nodeplugin-8zbcq /]# mount -t cvmfs atlas.cern.ch /mnt -v
CernVM-FS: running with credentials 999:997
CernVM-FS: loading Fuse module... Failed to initialize root file catalog (16 - file catalog failure)

And

kubectl get cm -l app=cvmfs-csi -o yaml

apiVersion: v1
items:
- apiVersion: v1
  kind: ConfigMap
  metadata:
    annotations:
      meta.helm.sh/release-name: cvmfs
      meta.helm.sh/release-namespace: cloudman
    creationTimestamp: "2022-12-11T06:07:55Z"
    labels:
      app: cvmfs-csi
      app.kubernetes.io/managed-by: Helm
      chart: cvmfs-csi-2.0.0
      heritage: Helm
    name: cvmfs-csi-config-d
    namespace: cloudman
    resourceVersion: "2263885"
    uid: cc268dbf-e3d3-42c0-bbe7-92761f588f16
- apiVersion: v1
  data:
    default.local: |
      CVMFS_USE_GEOAPI=yes
      CVMFS_HTTP_PROXY="http://ca-proxy.cern.ch:3128"

      # It is advised to change these configs in the cache section of the helm values
      # and leave them unchanged here, so they auto-generate.
      CVMFS_QUOTA_LIMIT=1000
      CVMFS_CACHE_BASE=/cvmfs-localcache
  kind: ConfigMap
  metadata:
    annotations:
      meta.helm.sh/release-name: cvmfs
      meta.helm.sh/release-namespace: cloudman
    creationTimestamp: "2022-12-11T06:07:55Z"
    labels:
      app: cvmfs-csi
      app.kubernetes.io/managed-by: Helm
      chart: cvmfs-csi-2.0.0
      heritage: Helm
    name: cvmfs-csi-default-local
    namespace: cloudman
    resourceVersion: "2263886"
    uid: 50fa8566-2087-4d0f-85cb-36f1946febc5
kind: List
metadata:
  resourceVersion: ""
  selfLink: "

Answer 3 · 2022-12-12T13:58:10.000Z

Can you try running with CVMFS_HTTP_PROXY=DIRECT in client configuration?

Answer 4 · 2022-12-12T15:09:42.000Z

That fixed the issue! Thanks for that. I suppose a settable value for the proxy would make it easier. Shall I issue a PR with
cvmfsConfig.proxy as the value in default.local?:

    default.local: |
      CVMFS_USE_GEOAPI=yes
      CVMFS_HTTP_PROXY="{{ .Values.cvmfsConfig.proxy }}"

Answer 5 · 2022-12-12T15:30:10.000Z

Cool! Actually no, the preferred way is to keep this in the config itself for now. Also please note that in production it is advised to set up some sort of cache (local and Squid proxy).

I'm closing this issue, but please do feel free to re-open or open a new one should you have more questions.