Skip to content

NodePublishVolume can hang after a successful mount, permanently leaking its VolumeLocks entry (requires driver pod restart to recover) #86

Description

@smtribal

What happened:
The driver can get into a state where a volume becomes permanently unmountable. We observed two related failure modes on the same shared RWX S3-backed PV, mounted concurrently by many pods (batch CronJob pods) on the same node:

  1. Permanently wedged lock, no self-recovery. A pod's NodePublishVolume call first logged rpc error: code = DeadlineExceeded desc = context deadline exceeded (kubelet gave up on the RPC). From that point on, every subsequent kubelet retry for the same volume/target path got rpc error: code = Aborted desc = An operation with the given Volume ID <x> already exists — continuously, 113 times over 32 minutes, with no recovery. We confirmed via mount on the node that the underlying fuse.rclone mount for that exact target path was actually present and healthy the entire time. This proves the original NodePublishVolume call successfully completed the mount but its goroutine never returned — so its defer VolumeLocks.Release(...) never fired, leaving the lock held forever. The only fix was restarting the csi-rclone-node pod on that node.

  2. Idempotency violation on already-mounted targets. Separately, we saw NodePublishVolume log Target path .../mount is already mounted (from prepareTargetDirectory), but instead of returning success, it proceeded to attempt mounting again and failed with failed to mount FUSE fs: directory already mounted, use --allow-non-empty to mount anyway.

What you expected to happen:
NodePublishVolume/NodeUnpublishVolume should complete within a bounded time, or fail and reliably release their VolumeLocks entry — a stuck internal operation should never permanently block all future retries for that volume/target path.

Per the CSI spec, NodePublishVolume against an already-mounted, healthy target path should be treated as an idempotent no-op success, not attempted again and allowed to fail against the driver's own existing mount.

How to reproduce it:
Not reliably reproducible on demand — occurs intermittently under sustained concurrent load: a shared ReadWriteMany S3-backed PV mounted by many short-lived Job pods on the same node, with --vfs-cache-mode=full and related VFS mount options. Appears more frequently the more concurrent mount/unmount activity there is against the same node and volume; we haven't isolated a minimal single-mount repro.

Anything else we need to know?:
VolumeLocks.TryAcquire/Release are keyed on volumeID + "-" + targetPath (pkg/rclone/nodeserver.go:822,927), with Release deferred immediately after a successful acquire (nodeserver.go:826,931) — so in principle it should always run. But nothing bounds how long the function body between acquire and return can take.

The mount's internal working context is created via context.WithCancel(context.TODO()) (nodeserver.go:431), fully decoupled from the incoming gRPC request's own context/deadline. There is no context.WithTimeout/deadline anywhere in nodeserver.go. So even after kubelet's own call times out client-side (DeadlineExceeded), the driver's internal goroutine keeps running/blocking with nothing to bound it.

Suspect concurrent load is a trigger/amplifier (many pods sharing one driver process per node, one node-local cache dir, and one S3 bucket — possible resource contention or S3 throttling), but haven't confirmed the exact stuck call via profiling/goroutine dump.

  1. The permanent-wedge sequence (kubectl describe pod events):
Warning  FailedMount             38m                 kubelet   MountVolume.SetUp failed for volume "example-cust-integration-pv" : rpc error: code = DeadlineExceeded desc = context deadline exceeded
Warning  FailedMount             6s (x113 over 32m)  kubelet   MountVolume.SetUp failed for volume "example-cust-integration-pv" : rpc error: code = Aborted desc = An operation with the given Volume ID example-cust-integration-pv already exists

  1. Confirmation the underlying mount was healthy the entire time it was "stuck" (mount output on the node, matched to the exact pod UID from the events above):
s3:example-cust-integration on /var/lib/kubelet/pods/d27640a6-9775-4727-a719-39f2d11d2cf9/volumes/kubernetes.io~csi/example-cust-integration-pv/mount type fuse.rclone (rw,nosuid,nodev,relatime,user_id=0,group_id=0,allow_other)
  1. The idempotency-violation sequence (driver pod logs, csi-rclone-node container):
I0716 08:17:56.189239       1 nodeserver.go:295] Target path /var/lib/kubelet/pods/4b3ed20d-f0ab-49e7-ac1b-09e6257fd486/volumes/kubernetes.io~csi/example-cust-integration-pv/mount is already mounted
I0716 08:17:56.189249       1 nodeserver.go:868] NodePublishVolume: mounting s3:example-cust-integration at /var/lib/kubelet/pods/4b3ed20d-f0ab-49e7-ac1b-09e6257fd486/volumes/kubernetes.io~csi/example-cust-integration-pv/mount
I0716 08:17:56.189301       1 nodeserver.go:883] Using configData with 1 remotes, resolving remote: s3:example-cust-integration
E0716 08:17:56.193704       1 utils.go:145] GRPC error: rpc error: code = Internal desc = failed to mount: failed to mount FUSE fs: directory already mounted, use --allow-non-empty to mount anyway: /var/lib/kubelet/pods/4b3ed20d-f0ab-49e7-ac1b-09e6257fd486/volumes/kubernetes.io~csi/example-cust-integration-pv/mount
  1. The original symptom that kicked this off (repeating GRPC error/call trace):
rclone E0715 15:48:29.448409       1 utils.go:145] GRPC error: rpc error: code = Aborted desc = An operation with the given Volume ID example-cust-integration-pv already exists
rclone I0715 15:48:29.550140       1 utils.go:140] GRPC call: /csi.v1.Node/NodeUnpublishVolume

Environment:

  • CSI Driver version: Helm chart csi-driver-rclone 0.4.11 (ghcr.io/veloxpack/charts/csi-driver-rclone:0.4.11)
  • Kubernetes version: Server Version: v1.34.9-eks-8f14419
  • OS: Linux (Bottlerocket OS 1.62.1 (aws-k8s-1.34))
  • Kernel: 6.12.88
  • Rclone version: v1.73.4
  • Storage backend: S3 (AWS), region eu-west-2, server_side_encryption = aws:kms
  • Install tools: Helm, via FluxCD HelmRelease (chart pulled from an OCIRepository)
  • Others: Mount options in use: uid=1500, gid=1500, allow-other, allow-delete, region eu-west-2, allow-overwrite, --vfs-cache-mode=full, --cache-dir=/mnt/rclone-cache, --vfs-cache-max-size=2G, --vfs-cache-max-age=24h, --dir-cache-time=5m, --vfs-read-chunk-size=64M, --vfs-read-chunk-size-limit=2G, --vfs-cache-poll-interval=30s, --vfs-write-back=0s. Volume access mode: ReadWriteMany, mounted concurrently by multiple short-lived Kubernetes Job pods.

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions