Fails to access large directories

jacksgt commented 1 year ago

Hi,

we have a case where a user tries to access a large directory (200+GB), but is fails with a generic error message. Reproducer:

$ kubectl create -f - <<EOF
apiVersion: v1
kind: PersistentVolumeClaim
metadata:
  name: cvmfs
spec:
  accessModes:
  - ReadOnlyMany
  resources:
    requests:
      # Volume size value has no effect and is ignored
      # by the driver, but must be non-zero.
      storage: 1
  storageClassName: cvmfs
---
apiVersion: v1
kind: Pod
metadata:
  name: cvmfs-demo
spec:
  containers:
    - name: demo
      image: busybox
      imagePullPolicy: IfNotPresent
      command: [ "/bin/sh", "-c", "trap : TERM INT; (while true; do sleep 1000; done) & wait" ]
      volumeMounts:
        - name: cvmfs
          mountPath: /cvmfs
          # CVMFS automount volumes must be mounted with HostToContainer mount propagation.
          mountPropagation: HostToContainer
  volumes:
    - name: cvmfs
      persistentVolumeClaim:
        claimName: cvmfs
EOF

$ kubectl exec -it cvmfs-demo -- /bin/sh
/ # ls /cvmfs/atlas.cern.ch/repo/sw/software/23.0/Athena/23.0.26
ls: /cvmfs/atlas.cern.ch/repo/sw/software/23.0/Athena/23.0.26: Input/output error
/ # ls /cvmfs/atlas.cern.ch/repo/sw/software/23.0/
AthSimulation           Athena                  DetCommon               atlas                   tdaq
AthSimulationExternals  AthenaExternals         Geant4                  sw                      tdaq-common
/ # ls /cvmfs/atlas.cern.ch/repo/sw/software/23.0/Athena/
ls: can't open '/cvmfs/atlas.cern.ch/repo/sw/software/23.0/Athena/': Input/output error

Logs from the nodeplugin:

$ kubectl -n kube-system logs cern-magnum-cvmfs-csi-nodeplugin-fn6zh -c nodeplugin
I0614 08:00:30.816995    7836 main.go:95] Running CVMFS CSI plugin with [/csi-cvmfsplugin -v=4 --nodeid=jack-test-cvmfs-dik24wgoresr-node-0 --endpoint=unix:///var/lib/kubelet/plugins/cvmfs.csi.cern.ch/csi.sock --drivername=cvmfs.csi.cern.ch --start-automount-daemon=true --automount-startup-timeout=5 --automount-unmount-timeout=600 --role=identity,node --has-alien-cache=false]
I0614 08:00:30.817074    7836 driver.go:149] Driver: cvmfs.csi.cern.ch
I0614 08:00:30.817078    7836 driver.go:151] Version: v2.1.1 (commit: a90329e7bf6bfe1d936168d286af6219f9a36a80; build time: 2023-06-14 08:00:30.815615071 +0000 UTC m=+0.001888489; metadata: )
I0614 08:00:30.817105    7836 driver.go:165] Registering Identity server
I0614 08:00:30.817144    7836 driver.go:220] Exec-ID 1: Running command env=[] prog=/usr/bin/cvmfs2 args=[cvmfs2 --version]
I0614 08:00:30.820747    7836 driver.go:220] Exec-ID 1: Process exited: exit status 0
I0614 08:00:30.820766    7836 driver.go:180] CernVM-FS version 2.10.0
I0614 08:00:30.820813    7836 driver.go:237] Exec-ID 2: Running command env=[] prog=/usr/bin/cvmfs_config args=[cvmfs_config setup]
I0614 08:00:31.837351    7836 driver.go:237] Exec-ID 2: Process exited: exit status 0
I0614 08:00:31.837518    7836 driver.go:292] Exec-ID 3: Running command env=[] prog=/usr/sbin/automount args=[automount --verbose]
I0614 08:00:31.851252    7836 driver.go:292] Exec-ID 3: Process exited: exit status 0
I0614 08:00:31.851301    7836 driver.go:250] Exec-ID 4: Running command env=[] prog=/usr/bin/mount args=[mount --make-shared /cvmfs]
I0614 08:00:31.852237    7836 driver.go:250] Exec-ID 4: Process exited: exit status 0
I0614 08:00:31.852251    7836 driver.go:197] Registering Node server with capabilities []
I0614 08:00:31.852415    7836 grpcserver.go:106] Listening for connections on /var/lib/kubelet/plugins/cvmfs.csi.cern.ch/csi.sock
I0614 08:00:32.903601    7836 grpcserver.go:136] Call-ID 1: Call: /csi.v1.Identity/GetPluginInfo
I0614 08:00:32.904568    7836 grpcserver.go:137] Call-ID 1: Request: {}
I0614 08:00:32.904612    7836 grpcserver.go:143] Call-ID 1: Response: {"name":"cvmfs.csi.cern.ch","vendor_version":"v2.1.1"}
I0614 08:00:33.559631    7836 grpcserver.go:136] Call-ID 2: Call: /csi.v1.Node/NodeGetInfo
I0614 08:00:33.559685    7836 grpcserver.go:137] Call-ID 2: Request: {}
I0614 08:00:33.559758    7836 grpcserver.go:143] Call-ID 2: Response: {"node_id":"jack-test-cvmfs-dik24wgoresr-node-0"}
I0614 08:03:49.148476    7836 grpcserver.go:136] Call-ID 3: Call: /csi.v1.Node/NodeGetCapabilities
I0614 08:03:49.148551    7836 grpcserver.go:137] Call-ID 3: Request: {}
I0614 08:03:49.148668    7836 grpcserver.go:143] Call-ID 3: Response: {}
I0614 08:03:49.149891    7836 grpcserver.go:136] Call-ID 4: Call: /csi.v1.Node/NodeGetCapabilities
I0614 08:03:49.149954    7836 grpcserver.go:137] Call-ID 4: Request: {}
I0614 08:03:49.149979    7836 grpcserver.go:143] Call-ID 4: Response: {}
I0614 08:03:49.150370    7836 grpcserver.go:136] Call-ID 5: Call: /csi.v1.Node/NodeGetCapabilities
I0614 08:03:49.150425    7836 grpcserver.go:137] Call-ID 5: Request: {}
I0614 08:03:49.150444    7836 grpcserver.go:143] Call-ID 5: Response: {}
I0614 08:03:49.151368    7836 grpcserver.go:136] Call-ID 6: Call: /csi.v1.Node/NodeGetCapabilities
I0614 08:03:49.151430    7836 grpcserver.go:137] Call-ID 6: Request: {}
I0614 08:03:49.151457    7836 grpcserver.go:143] Call-ID 6: Response: {}
I0614 08:03:49.153965    7836 grpcserver.go:136] Call-ID 7: Call: /csi.v1.Node/NodePublishVolume
I0614 08:03:49.154125    7836 grpcserver.go:137] Call-ID 7: Request: {"target_path":"/var/lib/kubelet/pods/ef9506a5-a038-4bc8-a483-5efb21a6da36/volumes/kubernetes.io~csi/pvc-0a836218-b8e6-4f24-ac82-ee00b03e444c/mount","volume_capability":{"AccessType":{"Mount":{}},"access_mode":{"mode":3}},"volume_context":{"storage.kubernetes.io/csiProvisionerIdentity":"1686729550118-8081-cvmfs.csi.cern.ch"},"volume_id":"pvc-0a836218-b8e6-4f24-ac82-ee00b03e444c"}
I0614 08:03:49.155342    7836 mountutil.go:75] Exec-ID 5: Running command env=[] prog=/usr/bin/mount args=[mount /cvmfs /var/lib/kubelet/pods/ef9506a5-a038-4bc8-a483-5efb21a6da36/volumes/kubernetes.io~csi/pvc-0a836218-b8e6-4f24-ac82-ee00b03e444c/mount --rbind --make-slave]
I0614 08:03:49.156541    7836 mountutil.go:75] Exec-ID 5: Process exited: exit status 0
I0614 08:03:49.156587    7836 grpcserver.go:143] Call-ID 7: Response: {}
I0614 08:04:32.359839    7836 grpcserver.go:136] Call-ID 8: Call: /csi.v1.Node/NodeGetCapabilities
I0614 08:04:32.360061    7836 grpcserver.go:137] Call-ID 8: Request: {}
I0614 08:04:32.360101    7836 grpcserver.go:143] Call-ID 8: Response: {}
I0614 08:05:29.260958    7836 grpcserver.go:136] Call-ID 9: Call: /csi.v1.Node/NodeUnpublishVolume
I0614 08:05:29.261201    7836 grpcserver.go:137] Call-ID 9: Request: {"target_path":"/var/lib/kubelet/pods/ef9506a5-a038-4bc8-a483-5efb21a6da36/volumes/kubernetes.io~csi/pvc-0a836218-b8e6-4f24-ac82-ee00b03e444c/mount","volume_id":"pvc-0a836218-b8e6-4f24-ac82-ee00b03e444c"}
I0614 08:05:29.261355    7836 mountutil.go:99] Exec-ID 6: Running command env=[] prog=/usr/bin/umount args=[umount --recursive /var/lib/kubelet/pods/ef9506a5-a038-4bc8-a483-5efb21a6da36/volumes/kubernetes.io~csi/pvc-0a836218-b8e6-4f24-ac82-ee00b03e444c/mount]
I0614 08:05:29.265108    7836 mountutil.go:99] Exec-ID 6: Process exited: exit status 0
I0614 08:05:29.265294    7836 grpcserver.go:143] Call-ID 9: Response: {}
I0614 08:05:29.362572    7836 grpcserver.go:136] Call-ID 10: Call: /csi.v1.Node/NodeGetCapabilities
I0614 08:05:29.362783    7836 grpcserver.go:137] Call-ID 10: Request: {}
I0614 08:05:29.362833    7836 grpcserver.go:143] Call-ID 10: Response: {}
I0614 08:06:04.227396    7836 grpcserver.go:136] Call-ID 11: Call: /csi.v1.Node/NodeGetCapabilities
I0614 08:06:04.227436    7836 grpcserver.go:137] Call-ID 11: Request: {}
I0614 08:06:04.227448    7836 grpcserver.go:143] Call-ID 11: Response: {}
I0614 08:06:04.229122    7836 grpcserver.go:136] Call-ID 12: Call: /csi.v1.Node/NodeGetCapabilities
I0614 08:06:04.229149    7836 grpcserver.go:137] Call-ID 12: Request: {}
I0614 08:06:04.229159    7836 grpcserver.go:143] Call-ID 12: Response: {}
I0614 08:06:04.229797    7836 grpcserver.go:136] Call-ID 13: Call: /csi.v1.Node/NodeGetCapabilities
I0614 08:06:04.229949    7836 grpcserver.go:137] Call-ID 13: Request: {}
I0614 08:06:04.230027    7836 grpcserver.go:143] Call-ID 13: Response: {}
I0614 08:06:04.230514    7836 grpcserver.go:136] Call-ID 14: Call: /csi.v1.Node/NodeGetCapabilities
I0614 08:06:04.230609    7836 grpcserver.go:137] Call-ID 14: Request: {}
I0614 08:06:04.230679    7836 grpcserver.go:143] Call-ID 14: Response: {}
I0614 08:06:04.231181    7836 grpcserver.go:136] Call-ID 15: Call: /csi.v1.Node/NodePublishVolume
I0614 08:06:04.231238    7836 grpcserver.go:137] Call-ID 15: Request: {"target_path":"/var/lib/kubelet/pods/4d81609b-5fba-4c63-a1a7-265a33b13729/volumes/kubernetes.io~csi/pvc-74ad843d-083b-4f9b-ae66-4ed691a37322/mount","volume_capability":{"AccessType":{"Mount":{}},"access_mode":{"mode":3}},"volume_context":{"storage.kubernetes.io/csiProvisionerIdentity":"1686729550118-8081-cvmfs.csi.cern.ch"},"volume_id":"pvc-74ad843d-083b-4f9b-ae66-4ed691a37322"}
I0614 08:06:04.231692    7836 mountutil.go:75] Exec-ID 7: Running command env=[] prog=/usr/bin/mount args=[mount /cvmfs /var/lib/kubelet/pods/4d81609b-5fba-4c63-a1a7-265a33b13729/volumes/kubernetes.io~csi/pvc-74ad843d-083b-4f9b-ae66-4ed691a37322/mount --rbind --make-slave]
I0614 08:06:04.233541    7836 mountutil.go:75] Exec-ID 7: Process exited: exit status 0
I0614 08:06:04.233563    7836 grpcserver.go:143] Call-ID 15: Response: {}

Please advise how to troubleshoot the issue further.

gman0 commented 1 year ago

Hi @jacksgt, assuming you're using v2.2.0 with all defaults, I'm able to reproduce this:

/atlas.cern.ch/repo/sw/software/23.0 # ls Athena
ls: can't open 'Athena': Input/output error

It seems the local cache is running out of space:

(cvmfs) cvmfs_lookup in parent inode: 5950 for name: Athena    [06-15-2023 14:25:00 UTC]
(lru) lookup inode --> path: 5950 (hit)    [06-15-2023 14:25:00 UTC]
(lru) lookup md5 --> dirent: acad9e5e6523aeaa78d5d0788262ed0f (miss)    [06-15-2023 14:25:00 UTC]
(catalog) looking up '/repo/sw/software/23.0/Athena' in catalog: '/repo/sw/software/23.0'    [06-15-2023 14:25:00 UTC]
(catalog) found entry '/repo/sw/software/23.0/Athena' in catalog '/repo/sw/software/23.0'    [06-15-2023 14:25:00 UTC]
(cvmfs) cvmfs_opendir on inode: 9203    [06-15-2023 14:25:00 UTC]
(lru) lookup inode --> path: 9203 (miss)    [06-15-2023 14:25:00 UTC]
(cvmfs) MISS 9203 - looking in inode tracker    [06-15-2023 14:25:00 UTC]
(lru) insert inode --> path 9203 -> '/repo/sw/software/23.0/Athena'    [06-15-2023 14:25:00 UTC]
(lru) lookup inode --> dirent: 9203 (miss)    [06-15-2023 14:25:00 UTC]
(catalog) looking up '/repo/sw/software/23.0/Athena' in catalog: '/repo/sw/software/23.0'    [06-15-2023 14:25:00 UTC]
(catalog) found entry '/repo/sw/software/23.0/Athena' in catalog '/repo/sw/software/23.0'    [06-15-2023 14:25:00 UTC]
(lru) insert inode --> dirent: 9203 -> 'Athena'    [06-15-2023 14:25:00 UTC]
(cvmfs) cvmfs_opendir on inode: 9203, path /repo/sw/software/23.0/Athena    [06-15-2023 14:25:00 UTC]
(cvmfs) Add to listing: ., inode 9203    [06-15-2023 14:25:00 UTC]
(lru) lookup md5 --> dirent: 39d14008a5c5b9c7e45809a51a014812 (miss)    [06-15-2023 14:25:00 UTC]
(catalog) looking up '/repo/sw/software/23.0' in catalog: '/repo/sw/software/23.0'    [06-15-2023 14:25:00 UTC]
(catalog) found entry '/repo/sw/software/23.0' in catalog '/repo/sw/software/23.0'    [06-15-2023 14:25:00 UTC]
(lru) insert md5 --> dirent: 39d14008a5c5b9c7e45809a51a014812 -> '23.0'    [06-15-2023 14:25:00 UTC]
(cvmfs) Add to listing: .., inode 5950    [06-15-2023 14:25:00 UTC]
(catalog) load nested catalog at /repo/sw/software/23.0/Athena    [06-15-2023 14:25:00 UTC]
(cache) miss ./60/620c17940f07abb77add368960016c20c75d75 (-2)    [06-15-2023 14:25:00 UTC]
(cache) miss ./60/620c17940f07abb77add368960016c20c75d75 (-2)    [06-15-2023 14:25:00 UTC]
(cache) downloading file catalog at atlas.cern.ch:/repo/sw/software/23.0/Athena (60620c17940f07abb77add368960016c20c75d75)    [06-15-2023 14:25:00 UTC]
(cache) start transaction on ./txn/fetchFj3QSc has result 55    [06-15-2023 14:25:00 UTC]
(cache) miss: file catalog at atlas.cern.ch:/repo/sw/software/23.0/Athena (60620c17940f07abb77add368960016c20c75d75) /data/60/620c17940f07abb77add368960016c20c75d75C    [06-15-2023 14:25:00 UTC]
(download) escaped http://cvmfs-stratum-one.cern.ch/cvmfs/atlas.cern.ch/data/60/620c17940f07abb77add368960016c20c75d75C to http://cvmfs-stratum-one.cern.ch/cvmfs/atlas.cern.ch/data/60/620c17940f07abb77add368960016c20c75d75C    [06-15-2023 14:25:00 UTC]
(download) Verify downloaded url /data/60/620c17940f07abb77add368960016c20c75d75C, proxy http://188.184.28.244:3128 (curl error 0)    [06-15-2023 14:25:06 UTC]
(cache) finished downloading of /data/60/620c17940f07abb77add368960016c20c75d75C    [06-15-2023 14:25:06 UTC]
(cache) commit ./60/620c17940f07abb77add368960016c20c75d75 ./txn/fetchFj3QSc    [06-15-2023 14:25:06 UTC]
(quota) pin into lru 60620c17940f07abb77add368960016c20c75d75, path file catalog at atlas.cern.ch:/repo/sw/software/23.0/Athena (60620c17940f07abb77add368960016c20c75d75)    [06-15-2023 14:25:06 UTC]
(quota) received command 2    [06-15-2023 14:25:06 UTC]
(quota) reserve 728374272 bytes for 60620c17940f07abb77add368960016c20c75d75    [06-15-2023 14:25:06 UTC]
(quota) failed to insert 60620c17940f07abb77add368960016c20c75d75 (pinned), no space    [06-15-2023 14:25:06 UTC]
(cache) commit failed: cannot pin 60620c17940f07abb77add368960016c20c75d75    [06-15-2023 14:25:06 UTC]
(catalog) failed to load catalog '/repo/sw/software/23.0/Athena' (2 - not enough space to load catalog)    [06-15-2023 14:25:06 UTC]

The default local cache limit is 1000MiB, which is being set in your cvmfs-csi-default-local ConfigMap. It is worth noting that the volume where the cache is stored is an emptyDir.

There are two ways to handle this:

If you have enough disk space on the node, you could set cache.local.cvmfsQuotaLimit to a higher value (and possibly set cache.local.volumeSpec to a hostPath
- however, if you're deploying this driver as a subchart, beware https://github.com/helm/helm/issues/9027 ; if this is the case, as a workaround you could play around with nodeplugin.extraMounts and nodeplugin.automount.extraVolumeMounts, and set CVMFS_CACHE_BASE accordingly)). 2000MiB seems to be enough, but with multiple users accessing other large repos this might not be enough still -- needs more testing.
You could set up Alien cache volume, and set it in cache.alien. Beware that there is currently no mechanism in place that would automatically clean up the cache volume when it becomes full.

By the way, you can get this log output by setting logLevelVerbosity to at least 5 in the chart, and set CVMFS_DEBUGLOG parameter in your client config (either in the global config via the cvmfs-csi-default-local ConfigMap, or a separate client config with the clientConfig volume parameter).

jacksgt commented 1 year ago

Hi Robert, thanks for the excellent troubleshooting and workaround suggestions! It seems like on LXPLUS they're using a higher quota limit (default is 1000):

[lxplus924 ~]$ grep CVMFS_QUOTA_LIMIT /etc/cvmfs/default.local 
CVMFS_QUOTA_LIMIT='20000'

What exactly is this quota limit? Does it apply to all CVMFS mounts or is it per repository?

jacksgt commented 1 year ago

Answering my own question:

What exactly is this quota limit? Does it apply to all CVMFS mounts or is it per repository?

CVMFS docs say:

Each repository can either have an exclusive cache or join the CernVM-FS shared cache. The shared cache enforces a common quota for all repositories used on the host. File duplicates across repositories are stored only once in the shared cache. The quota limit of the shared directory should be at least the maximum of the recommended limits of its participating repositories.

and also:

Once the quota limit is reached, CernVM-FS will automatically remove files from the cache according to the least recently used policy. Removal of files is performed bunch-wise until half of the maximum cache size has been freed. The quota limit can be set in Megabytes by CVMFS_QUOTA_LIMIT. For typical repositories, a few Gigabytes make a good quota limit.

https://cvmfs.readthedocs.io/en/stable/cpt-configure.html#cache-settings

cvmfs-contrib / cvmfs-csi

Fails to access large directories #89