DeepDive: CSI PVC Unmount Failed - Cannot Find vol_data.json

Posted on In

DeepDive: CustomCSI PVC UnMount Failed With Can Not Find The vol_data.json File

Here is the whole story
volume success mount at Jun 2 20:31:15

Jun 2 20:31:15 k8s-node-1 kubelet[11702]: I0602 20:31:15.512970 11702 operation_generator.go:763] “MountVolume.SetUp succeeded for volume \“pvc-51e441b1-2358-4c5d-bb10-1f75d59d25fc\“ storageclass csi-performance-ha (UniqueName: \“kubernetes.io/csi/com.example.sds.custom-csi^pvc-51e441b1-2358-4c5d-bb10-1f75d59d25fc\“) pod \“jupyter-zimguo\“ (UID: \“183d9a26-22fc-4d5e-bff2-b41d7b5b7e10\“) “ pod=”prod-ns/jupyter-zimguo”

2025-06-03 01:58:43 begin os patching:

“{\“status\“:{\“conditions\“:[{\“lastTransitionTime\“:\“2025-05-27T05:59:40Z\“,\“status\“:\“True\“,\“type\“:\“Initialized\“},{\“lastProbeTime\“:\“2025-06-03T08:58:43Z\“,\“lastTransitionTime\“:\“2025-06-03T08:58:43Z\“,\“message\“:\“Pod was marked into notReady due to os patching[2025-06-03 01:58:43.210829363 -0700 -07

Jun 3 02:02 the time of reboot

reboot system boot 6.8.0-60-generic Tue Jun 3 02:02 still running

02:02:19 The node boot and kubelet start remount volume

Jun 3 02:02:19 k8s-node-1 kubelet[5695]: I0603 02:02:19.672785 5695 reconciler_common.go:231] “operationExecutor.MountVolume started for volume \“pvc-51e441b1-2358-4c5d-bb10-1f75d59d25fc\“ storageclass csi-performance-ha (UniqueName: \“kubernetes.io/csi/com.example.sds.custom-csi^pvc-51e441b1-2358-4c5d-bb10-1f75d59d25fc\“) pod \“jupyter-zimguo\“ (UID: \“183d9a26-22fc-4d5e-bff2-b41d7b5b7e10\“) “ pod=”prod-ns/jupyter-zimguo”

02:02:21 Wait register CustomCSI csi driver

Jun 3 02:02:21 k8s-node-1 kubelet[5695]: E0603 02:02:21.303864 5695 nestedpendingoperations.go:348] Operation for “{volumeName:kubernetes.io/csi/com.example.sds.custom-csi^pvc-51e441b1-2358-4c5d-bb10-1f75d59d25fc podName: nodeName:}” failed. No retries permitted until 2025-06-03 02:02:23.303853029 -0700 -07 m=+5.472100283 (durationBeforeRetry 2s). Error: MountVolume.MountDevice failed for volume “pvc-51e441b1-2358-4c5d-bb10-1f75d59d25fc” storageclass csi-performance-ha (UniqueName: “kubernetes.io/csi/com.example.sds.custom-csi^pvc-51e441b1-2358-4c5d-bb10-1f75d59d25fc”) pod “jupyter-zimguo” (UID: “183d9a26-22fc-4d5e-bff2-b41d7b5b7e10”) : kubernetes.io/csi: attacher.MountDevice failed to create newCsiDriverClient: driver name com.example.sds.custom-csi not found in the list of registered CSI drivers

Continually to 02:02:51

Jun 3 02:02:51 k8s-node-1 kubelet[5695]: E0603 02:02:51.565995 5695 nestedpendingoperations.go:348] Operation for “{volumeName:kubernetes.io/csi/com.example.sds.custom-csi^pvc-51e441b1-2358-4c5d-bb10-1f75d59d25fc podName: nodeName:}” failed. No retries permitted until 2025-06-03 02:03:23.565986862 -0700 -07 m=+65.734234116 (durationBeforeRetry 32s). Error: MountVolume.MountDevice failed for volume “pvc-51e441b1-2358-4c5d-bb10-1f75d59d25fc” storageclass csi-performance-ha (UniqueName: “kubernetes.io/csi/com.example.sds.custom-csi^pvc-51e441b1-2358-4c5d-bb10-1f75d59d25fc”) pod “jupyter-zimguo” (UID: “183d9a26-22fc-4d5e-bff2-b41d7b5b7e10”) : kubernetes.io/csi: attacher.MountDevice failed to create newCsiDriverClient: driver name com.example.sds.custom-csi not found in the list of registered CSI drivers

Jun 3 02:02:51 k8s-node-1 kubelet[5695]: I0603 02:02:51.680442 5695 plugin_watcher.go:194] “Adding socket path or updating timestamp to desired state cache” path=”/var/mnt/kubelet/plugins_registry/com.example.sds.custom-csi-reg.sock”

02:02:46 start delete pod

2025-06-03T09:02:46.328940Z system:serviceaccount:prod-ns:hub delete ResponseComplete 200

Jun 3 02:02:48 k8s-node-1 kubelet[5695]: I0603 02:02:48.993413 5695 kubelet.go:2466] “SyncLoop REMOVE” source=”api” pods=[“prod-ns/jupyter-zimguo”]

Jun 3 02:02:46 k8s-node-1 kubelet[5695]: I0603 02:02:46.589967 5695 kubelet.go:2472] “SyncLoop DELETE” source=”api” pods=[“prod-ns/jupyter-zimguo”]

Jun 3 02:02:46 k8s-node-1 kubelet[5695]: I0603 02:02:46.365756 5695 kubelet.go:2472] “SyncLoop DELETE” source=”api” pods=[“prod-ns/jupyter-zimguo”]

Due to the current pod’volume not mounted and container not started, the pod deleted successfully.

02:03:23 global mount(NodeStageVolume) success, and here should have saved the vol_data.json

Jun 3 02:03:23 k8s-node-1 kubelet[5695]: I0603 02:03:23.655384 5695 operation_generator.go:706] “MountVolume.MountDevice succeeded for volume \“pvc-51e441b1-2358-4c5d-bb10-1f75d59d25fc\“ storageclass csi-performance-ha (UniqueName: \“kubernetes.io/csi/com.example.sds.custom-csi^pvc-51e441b1-2358-4c5d-bb10-1f75d59d25fc\“) pod \“jupyter-zimguo\“ (UID: \“183d9a26-22fc-4d5e-bff2-b41d7b5b7e10\“) device mount path \“/var/mnt/kubelet/plugins/kubernetes.io/csi/com.example.sds.custom-csi/e87e074abd78d05bd43695b22382976475eb7b7f4143f839307fe42d37b2a79c/globalmount\“” pod=”prod-ns/jupyter-zimguo”

We can see the global path is still on host
root@k8s-node-1:~# ls /var/mnt/kubelet/plugins/kubernetes.io/csi/com.example.sds.custom-csi/e87e074abd78d05bd43695b22382976475eb7b7f4143f839307fe42d37b2a79c/

globalmount vol_data.json

02:03:23 MountVolume.SetUp(NodePublishVolume) failed but saved the json file

Jun 3 02:03:23 k8s-node-1 kubelet[5695]: E0603 02:03:23.675438 5695 nestedpendingoperations.go:348] Operation for “{volumeName:kubernetes.io/csi/com.example.sds.custom-csi^pvc-51e441b1-2358-4c5d-bb10-1f75d59d25fc podName: nodeName:}” failed. No retries permitted until 2025-06-03 02:04:27.675413083 -0700 -07 m=+129.843660345 (durationBeforeRetry 1m4s). Error: MountVolume.SetUp failed for volume “pvc-51e441b1-2358-4c5d-bb10-1f75d59d25fc” storageclass csi-performance-ha (UniqueName: “kubernetes.io/csi/com.example.sds.custom-csi^pvc-51e441b1-2358-4c5d-bb10-1f75d59d25fc”) pod “jupyter-zimguo” (UID: “183d9a26-22fc-4d5e-bff2-b41d7b5b7e10”) : rpc error: code = Internal desc = 8a084a8b93056b5201944038687227ec - 10.200.15.12 - Failed while trying to attach iscsi partition

Then kubelet try to clean the mount after failed
err = csi.NodePublishVolume(
ctx,
volumeHandle,
readOnly,
deviceMountPath,
dir,
accessMode,
publishContext,
volAttribs,
nodePublishSecrets,
fsType,
mountOptions,
nodePublishFSGroupArg,
)

if err \!= nil {  
    // If operation finished with error then we can remove the mount directory.  
    if volumetypes.IsOperationFinishedError(err) {  
        if removeMountDirErr := removeMountDir(c.plugin, dir); removeMountDirErr \!= nil {  
            klog.Error(log("mounter.SetupAt failed to remove mount dir after a NodePublish() error \[%s\]: %v", dir, removeMountDirErr))  
        }  
    }  
    return err  
}

// removeMountDir cleans the mount dir when dir is not mounted and removed the volume data file in dir
func removeMountDir(plug *csiPlugin, mountPath string) error {
klog.V(4).Info(log(“removing mount path [%s]“, mountPath))

mnt, err := isDirMounted(plug, mountPath)  
if err \!= nil {  
    return err  
}  
if \!mnt {  
    klog.V(4).Info(log("dir not mounted, deleting it \[%s\]", mountPath))  
    if err := os.Remove(mountPath); err \!= nil && \!os.IsNotExist(err) {  
        return errors.New(log("failed to remove dir \[%s\]: %v", mountPath, err))  
    }  
    // remove volume data file as well  
    volPath := filepath.Dir(mountPath)  
    dataFile := filepath.Join(volPath, volDataFileName)  
    klog.V(4).Info(log("also deleting volume info data file \[%s\]", dataFile))  
    if err := os.Remove(dataFile); err \!= nil && \!os.IsNotExist(err) {  
        return errors.New(log("failed to delete volume data file \[%s\]: %v", dataFile, err))  
    }  
    // remove volume path  
    klog.V(4).Info(log("deleting volume path \[%s\]", volPath))  
    if err := os.Remove(volPath); err \!= nil && \!os.IsNotExist(err) {  
        return errors.New(log("failed to delete volume path \[%s\]: %v", volPath, err))  
    }  
}  
return nil

}

In this function you can see if the error returned from NodePublish is not from UncertainProgressError and TransientOperationFailure
// operation is finished with a FINAL error.
func IsOperationFinishedError(err error) bool {
if _, ok := err.(*UncertainProgressError); ok {
return false
}
if _, ok := err.(*TransientOperationFailure); ok {
return false
}
return true

}

and the pod target directory is not mounted, then remove the data json file

volDataFileName \= "vol\_data.json"

02:03:37 Finally the next time kubelet try to umount the volume, it report this error:

Jun 3 02:03:37 k8s-node-1 kubelet[5695]: E0603 02:03:37.772848 5695 reconciler_common.go:169] “operationExecutor.UnmountVolume failed (controllerAttachDetachEnabled true) for volume \“pvc-51e441b1-2358-4c5d-bb10-1f75d59d25fc\“ (UniqueName: \“kubernetes.io/csi/com.example.sds.custom-csi^pvc-51e441b1-2358-4c5d-bb10-1f75d59d25fc\“) pod \“183d9a26-22fc-4d5e-bff2-b41d7b5b7e10\“ (UID: \“183d9a26-22fc-4d5e-bff2-b41d7b5b7e10\“) : UnmountVolume.NewUnmounter failed for volume \“pvc-51e441b1-2358-4c5d-bb10-1f75d59d25fc\“ (UniqueName: \“kubernetes.io/csi/com.example.sds.custom-csi^pvc-51e441b1-2358-4c5d-bb10-1f75d59d25fc\“) pod \“183d9a26-22fc-4d5e-bff2-b41d7b5b7e10\“ (UID: \“183d9a26-22fc-4d5e-bff2-b41d7b5b7e10\“) : kubernetes.io/csi: unmounter failed to load volume data file [/var/mnt/kubelet/pods/183d9a26-22fc-4d5e-bff2-b41d7b5b7e10/volumes/kubernetes.io~csi/pvc-51e441b1-2358-4c5d-bb10-1f75d59d25fc/mount]: kubernetes.io/csi: failed to open volume data file [/var/mnt/kubelet/pods/183d9a26-22fc-4d5e-bff2-b41d7b5b7e10/volumes/kubernetes.io~csi/pvc-51e441b1-2358-4c5d-bb10-1f75d59d25fc/vol_data.json]: open /var/mnt/kubelet/pods/183d9a26-22fc-4d5e-bff2-b41d7b5b7e10/volumes/kubernetes.io~csi/pvc-51e441b1-2358-4c5d-bb10-1f75d59d25fc/vol_data.json: no such file or directory” err=”UnmountVolume.NewUnmounter failed for volume \“pvc-51e441b1-2358-4c5d-bb10-1f75d59d25fc\“ (UniqueName: \“kubernetes.io/csi/com.example.sds.custom-csi^pvc-51e441b1-2358-4c5d-bb10-1f75d59d25fc\“) pod \“183d9a26-22fc-4d5e-bff2-b41d7b5b7e10\“ (UID: \“183d9a26-22fc-4d5e-bff2-b41d7b5b7e10\“) : kubernetes.io/csi: unmounter failed to load volume data file [/var/mnt/kubelet/pods/183d9a26-22fc-4d5e-bff2-b41d7b5b7e10/volumes/kubernetes.io~csi/pvc-51e441b1-2358-4c5d-bb10-1f75d59d25fc/mount]: kubernetes.io/csi: failed to open volume data file [/var/mnt/kubelet/pods/183d9a26-22fc-4d5e-bff2-b41d7b5b7e10/volumes/kubernetes.io~csi/pvc-51e441b1-2358-4c5d-bb10-1f75d59d25fc/vol_data.json]: open /var/mnt/kubelet/pods/183d9a26-22fc-4d5e-bff2-b41d7b5b7e10/volumes/kubernetes.io~csi/pvc-51e441b1-2358-4c5d-bb10-1f75d59d25fc/vol_data.json: no such file or directory”

Then the kubelet not try to mount volume but only try to umount volume, then it report the error all the time.
The error function at here:
func (p *csiPlugin) NewUnmounter(specName string, podUID types.UID) (volume.Unmounter, error) {
klog.V(4).Info(log(“setting up unmounter for [name=%v, podUID=%v]“, specName, podUID))

kvh, ok := p.host.(volume.KubeletVolumeHost)  
if \!ok {  
    return nil, errors.New(log("cast from VolumeHost to KubeletVolumeHost failed"))  
}

unmounter := \&csiMountMgr{  
    plugin:       p,  
    podUID:       podUID,  
    specVolumeID: specName,  
    kubeVolHost:  kvh,  
}

// load volume info from file  
dir := unmounter.GetPath()  
dataDir := filepath.Dir(dir) // dropoff /mount at end  
data, err := loadVolumeData(dataDir, volDataFileName)  
if err \!= nil {  
    return nil, errors.New(log("unmounter failed to load volume data file \[%s\]: %v", dir, err))  
}  
unmounter.driverName \= csiDriverName(data\[volDataKey.driverName\])  
unmounter.volumeID \= data\[volDataKey.volHandle\]  
unmounter.csiClientGetter.driverName \= unmounter.driverName

return unmounter, nil

}

So according to this story, we can find some points to resolve the issue:

  1. Check why CustomCSI driver NodePublish failed after node patching(see timeline 02:03:23).
  2. Change the NodePublish return error type to match the UncertainProgressError or TransientOperationFailure to skip the json file removal(see the function IsOperationFinishedError).
  3. Stop patching before the Storage team fix this issue.
  4. Reproduction for this issue is to reboot the node then delete the pod before mount success.

Currently we can restart the kubelet with the original node which deleted’s pod attached to recover these PVCs.

Reference:

  1. Audit log:

[internal audit log URL]

  1. Kubelet log:

[internal monitoring log URL]

Other CustomCSI PVC Issues:

As we know, I have met 3 different cases of the CustomCSI issue they are looks similar:

  1. At here [[internal Slack thread]) , the kubelet report error “open /var/mnt/kubelet/pods/183d9a26-22fc-4d5e-bff2-b41d7b5b7e10/volumes/kubernetes.io~csi/pvc-51e441b1-2358-4c5d-bb10-1f75d59d25fc/vol_data.json: no such file or directory”. CustomCSI driver reports an error with `Failed while trying to attach iscsi partition` . Which is triggered by node restart and pod deletion. Need CustomCSI to check the driver code.
  2. [internal Slack thread] kubelet report driver can not register and kubelet connect the driver refused: `Err: connection error: desc = “transport: Error while dialing: dial unix /var/mnt/kubelet/plugins_registry/com.example.sds.custom-csi-reg.sock: connect: connection refused”`. The other csi plugins registered success. This issue has not seen the solution and RCA yet.
  3. [[internal Slack thread]) In this case, all csi driver register failed `driver name kubernetes.io.csi.local not found in the list of registered CSI drivers`. This is k8s known issue https://github.com/kubernetes/kubernetes/issues/127948, after reboot, kubelet failed to create the container. We have a pr to fix this issue https://github.com/kubernetes/kubernetes/issues/127948 (upstream fix PR). Wait core sig review and merge.