Topolvm LV deletion issue

[jurim76]

Hello
Recently I've got an issue during database chart upgrade in a k8 cluster
After pods redeploy, some database PVCs were in pending state with the error about missing volume id
I've checked topolvm-node logs and found that topolvm deleted a lot of LVs on physical nodes and data was completely lost for a half of databases in a cluster.
How to prevent this devastating behaviour?

Will nodeFinalize help?

controller:
  nodeFinalize:
    skipped: true

[llamerada-jp]

Let me ask you some questions to help us understand the context.

I've got an issue during database chart upgrade in a k8 cluster

What exactly did you do database chart upgrade? Does it mean you upgraded your DBMS product?

Will nodeFinalize help?...

Have you done any operations that recreate node resources? For example, CAPI re-creates node when node upgrade. So if you don't set that flag, PVC will be deleted.
related issue: #397

After pods redeploy, some database PVCs were in pending state with the error about missing volume id
I've checked topolvm-node logs and found that topolvm deleted a lot of LVs on physical nodes

Could you please show me the following actual logs?

• Event messages bound with the PVC and PV
• topolvm-node logs you found
• topolvm-controller logs around DeleteVolume called messages

[jurim76]

What exactly did you do database chart upgrade? Does it mean you upgraded your DBMS product?

Postgres image tag has been changed and chart recreated the database pods, but unfortunately chart template contains the error and pods didn't start

Have you done any operations that recreate node resources? For example, CAPI re-creates node when node upgrade. So if you don't set that flag, PVC will be deleted.
The upgrade was kubernetes cluster upgrade only to the next minor version. Also topolvm chart has been upgaded from 14.1.1 to 14.1.2.
Could you please clarify who is responsilbe for PVC deletion, if topolvm doesn't handle PVC directly?

Could you please show me the following actual logs?

I've checked some PV marked for deletion, let's check pvc-681b193f-006a-4186-8a43-c7da96cc88dd PV, it's a working PV for kafka pod

kubectl get pv pvc-681b193f-006a-4186-8a43-c7da96cc88dd
NAME                                       CAPACITY   ACCESS MODES   RECLAIM POLICY   STATUS   CLAIM                     STORAGECLASS       REASON   AGE
pvc-681b193f-006a-4186-8a43-c7da96cc88dd   100Gi      RWO            Delete           Bound    wynnbet-ma/kafka02-data   topolvm-ssd-ext4            44d

kubectl get pvc kafka02-data 
NAME           STATUS   VOLUME                                     CAPACITY   ACCESS MODES   STORAGECLASS       AGE
kafka02-data   Bound    pvc-681b193f-006a-4186-8a43-c7da96cc88dd   100Gi      RWO            topolvm-ssd-ext4   44d

descaled kafka sts with replica 0, pod terminated

kubectl get sts kafka02 
NAME      READY   AGE
kafka02   0/1     44d 

Check topolvm logs

{"level":"info","ts":"2024-05-13T11:10:40Z","logger":"driver.node","msg":"NodeGetVolumeStats is called","volume_id":"de6af941-057b-4ac3-a11c-392c427447e7","volume_path":"/var/lib/kubelet/pods/79357505-8c8e-49c7-9568-662ba7778c8f/volumes/kubernetes.io~csi/pvc-681b193f-006a-4186-8a43-c7da96cc88dd/mount"}
{"level":"info","ts":"2024-05-13T11:11:48Z","msg":"start finalizing LogicalVolume","controller":"logicalvolume","controllerGroup":"topolvm.cybozu.com","controllerKind":"LogicalVolume","LogicalVolume":{"name":"pvc-681b193f-006a-4186-8a43-c7da96cc88dd"},"namespace":"","name":"pvc-681b193f-006a-4186-8a43-c7da96cc88dd","reconcileID":"54b6ac54-1a34-4266-a687-22d8fa474bf3","name":"pvc-681b193f-006a-4186-8a43-c7da96cc88dd"}
{"level":"info","ts":"2024-05-13T11:11:48Z","msg":"invoking command","controller":"logicalvolume","controllerGroup":"topolvm.cybozu.com","controllerKind":"LogicalVolume","LogicalVolume":{"name":"pvc-681b193f-006a-4186-8a43-c7da96cc88dd"},"namespace":"","name":"pvc-681b193f-006a-4186-8a43-c7da96cc88dd","reconcileID":"54b6ac54-1a34-4266-a687-22d8fa474bf3","args":["/usr/bin/nsenter","-m","-u","-i","-n","-p","-t","1","/sbin/lvm","vgs","topolvm-vg-ssd","-o","vg_uuid,vg_name,vg_size,vg_free","--units","b","--nosuffix","--reportformat","json"]}
{"level":"info","ts":"2024-05-13T11:11:48Z","msg":"invoking command","controller":"logicalvolume","controllerGroup":"topolvm.cybozu.com","controllerKind":"LogicalVolume","LogicalVolume":{"name":"pvc-681b193f-006a-4186-8a43-c7da96cc88dd"},"namespace":"","name":"pvc-681b193f-006a-4186-8a43-c7da96cc88dd","reconcileID":"54b6ac54-1a34-4266-a687-22d8fa474bf3","args":["/usr/bin/nsenter","-m","-u","-i","-n","-p","-t","1","/sbin/lvm","lvremove","-f","topolvm-vg-ssd/de6af941-057b-4ac3-a11c-392c427447e7"]}
{"level":"error","ts":"2024-05-13T11:11:48Z","msg":"failed to remove volume","controller":"logicalvolume","controllerGroup":"topolvm.cybozu.com","controllerKind":"LogicalVolume","LogicalVolume":{"name":"pvc-681b193f-006a-4186-8a43-c7da96cc88dd"},"namespace":"","name":"pvc-681b193f-006a-4186-8a43-c7da96cc88dd","reconcileID":"54b6ac54-1a34-4266-a687-22d8fa474bf3","name":"de6af941-057b-4ac3-a11c-392c427447e7","name":"de6af941-057b-4ac3-a11c-392c427447e7","error":"exit status 5: Logical volume topolvm-vg-ssd/de6af941-057b-4ac3-a11c-392c427447e7 contains a filesystem in use.","stacktrace":"github.com/topolvm/topolvm/internal/lvmd.(*lvService).RemoveLV\n\t/workdir/internal/lvmd/lvservice.go:172\ngithub.com/topolvm/topolvm/internal/lvmd.(*embeddedServiceClients).RemoveLV\n\t/workdir/internal/lvmd/embed.go:143\ngithub.com/topolvm/topolvm/internal/controller.(*LogicalVolumeReconciler).removeLVIfExists\n\t/workdir/internal/controller/logicalvolume_controller.go:150\ngithub.com/topolvm/topolvm/internal/controller.(*LogicalVolumeReconciler).Reconcile\n\t/workdir/internal/controller/logicalvolume_controller.go:121\nsigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).Reconcile\n\t/go/pkg/mod/sigs.k8s.io/controller-runtime@v0.16.3/pkg/internal/controller/controller.go:119\nsigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).reconcileHandler\n\t/go/pkg/mod/sigs.k8s.io/controller-runtime@v0.16.3/pkg/internal/controller/controller.go:316\nsigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).processNextWorkItem\n\t/go/pkg/mod/sigs.k8s.io/controller-runtime@v0.16.3/pkg/internal/controller/controller.go:266\nsigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).Start.func2.2\n\t/go/pkg/mod/sigs.k8s.io/controller-runtime@v0.16.3/pkg/internal/controller/controller.go:227"}
{"level":"error","ts":"2024-05-13T11:11:48Z","msg":"failed to remove LV","controller":"logicalvolume","controllerGroup":"topolvm.cybozu.com","controllerKind":"LogicalVolume","LogicalVolume":{"name":"pvc-681b193f-006a-4186-8a43-c7da96cc88dd"},"namespace":"","name":"pvc-681b193f-006a-4186-8a43-c7da96cc88dd","reconcileID":"54b6ac54-1a34-4266-a687-22d8fa474bf3","name":"pvc-681b193f-006a-4186-8a43-c7da96cc88dd","uid":"de6af941-057b-4ac3-a11c-392c427447e7","error":"exit status 5: Logical volume topolvm-vg-ssd/de6af941-057b-4ac3-a11c-392c427447e7 contains a filesystem in use.","stacktrace":"github.com/topolvm/topolvm/internal/controller.(*LogicalVolumeReconciler).removeLVIfExists\n\t/workdir/internal/controller/logicalvolume_controller.go:156\ngithub.com/topolvm/topolvm/internal/controller.(*LogicalVolumeReconciler).Reconcile\n\t/workdir/internal/controller/logicalvolume_controller.go:121\nsigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).Reconcile\n\t/go/pkg/mod/sigs.k8s.io/controller-runtime@v0.16.3/pkg/internal/controller/controller.go:119\nsigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).reconcileHandler\n\t/go/pkg/mod/sigs.k8s.io/controller-runtime@v0.16.3/pkg/internal/controller/controller.go:316\nsigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).processNextWorkItem\n\t/go/pkg/mod/sigs.k8s.io/controller-runtime@v0.16.3/pkg/internal/controller/controller.go:266\nsigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).Start.func2.2\n\t/go/pkg/mod/sigs.k8s.io/controller-runtime@v0.16.3/pkg/internal/controller/controller.go:227"}
{"level":"error","ts":"2024-05-13T11:11:48Z","msg":"Reconciler error","controller":"logicalvolume","controllerGroup":"topolvm.cybozu.com","controllerKind":"LogicalVolume","LogicalVolume":{"name":"pvc-681b193f-006a-4186-8a43-c7da96cc88dd"},"namespace":"","name":"pvc-681b193f-006a-4186-8a43-c7da96cc88dd","reconcileID":"54b6ac54-1a34-4266-a687-22d8fa474bf3","error":"exit status 5: Logical volume topolvm-vg-ssd/de6af941-057b-4ac3-a11c-392c427447e7 contains a filesystem in use.","stacktrace":"sigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).reconcileHandler\n\t/go/pkg/mod/sigs.k8s.io/controller-runtime@v0.16.3/pkg/internal/controller/controller.go:329\nsigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).processNextWorkItem\n\t/go/pkg/mod/sigs.k8s.io/controller-runtime@v0.16.3/pkg/internal/controller/controller.go:266\nsigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).Start.func2.2\n\t/go/pkg/mod/sigs.k8s.io/controller-runtime@v0.16.3/pkg/internal/controller/controller.go:227"}
{"level":"info","ts":"2024-05-13T11:12:35Z","logger":"driver.node","msg":"NodeGetVolumeStats is called","volume_id":"de6af941-057b-4ac3-a11c-392c427447e7","volume_path":"/var/lib/kubelet/pods/79357505-8c8e-49c7-9568-662ba7778c8f/volumes/kubernetes.io~csi/pvc-681b193f-006a-4186-8a43-c7da96cc88dd/mount"}
{"level":"info","ts":"2024-05-13T11:20:20Z","logger":"driver.node","msg":"NodeUnpublishVolume called","volume_id":"de6af941-057b-4ac3-a11c-392c427447e7","target_path":"/var/lib/kubelet/pods/79357505-8c8e-49c7-9568-662ba7778c8f/volumes/kubernetes.io~csi/pvc-681b193f-006a-4186-8a43-c7da96cc88dd/mount"}
{"level":"info","ts":"2024-05-13T11:20:22Z","logger":"driver.node","msg":"NodeUnpublishVolume(fs) is succeeded","volume_id":"de6af941-057b-4ac3-a11c-392c427447e7","target_path":"/var/lib/kubelet/pods/79357505-8c8e-49c7-9568-662ba7778c8f/volumes/kubernetes.io~csi/pvc-681b193f-006a-4186-8a43-c7da96cc88dd/mount"}
{"level":"info","ts":"2024-05-13T11:20:23Z","logger":"driver.node","msg":"NodePublishVolume called","volume_id":"de6af941-057b-4ac3-a11c-392c427447e7","publish_context":null,"target_path":"/var/lib/kubelet/pods/5482ddf0-82be-4400-90cb-de85116f49d9/volumes/kubernetes.io~csi/pvc-681b193f-006a-4186-8a43-c7da96cc88dd/mount","volume_capability":"mount:<fs_type:\"ext4\" > access_mode:<mode:SINGLE_NODE_WRITER > ","read_only":false,"num_secrets":0,"volume_context":{"csi.storage.k8s.io/ephemeral":"false","csi.storage.k8s.io/pod.name":"kafka02-0","csi.storage.k8s.io/pod.namespace":"wynnbet-ma","csi.storage.k8s.io/pod.uid":"5482ddf0-82be-4400-90cb-de85116f49d9","csi.storage.k8s.io/serviceAccount.name":"kafka-cluster","storage.kubernetes.io/csiProvisionerIdentity":"1711674431379-5732-topolvm.cybozu.com"}}
{"level":"info","ts":"2024-05-13T11:20:23Z","logger":"driver.node","msg":"NodePublishVolume(fs) succeeded","volume_id":"de6af941-057b-4ac3-a11c-392c427447e7","target_path":"/var/lib/kubelet/pods/5482ddf0-82be-4400-90cb-de85116f49d9/volumes/kubernetes.io~csi/pvc-681b193f-006a-4186-8a43-c7da96cc88dd/mount","fstype":"ext4"}
{"level":"info","ts":"2024-05-13T11:20:34Z","logger":"driver.node","msg":"NodeGetVolumeStats is called","volume_id":"de6af941-057b-4ac3-a11c-392c427447e7","volume_path":"/var/lib/kubelet/pods/5482ddf0-82be-4400-90cb-de85116f49d9/volumes/kubernetes.io~csi/pvc-681b193f-006a-4186-8a43-c7da96cc88dd/mount"}
{"level":"info","ts":"2024-05-13T11:22:34Z","logger":"driver.node","msg":"NodeGetVolumeStats is called","volume_id":"de6af941-057b-4ac3-a11c-392c427447e7","volume_path":"/var/lib/kubelet/pods/5482ddf0-82be-4400-90cb-de85116f49d9/volumes/kubernetes.io~csi/pvc-681b193f-006a-4186-8a43-c7da96cc88dd/mount"}
{"level":"info","ts":"2024-05-13T11:23:45Z","logger":"driver.node","msg":"NodeUnpublishVolume called","volume_id":"de6af941-057b-4ac3-a11c-392c427447e7","target_path":"/var/lib/kubelet/pods/5482ddf0-82be-4400-90cb-de85116f49d9/volumes/kubernetes.io~csi/pvc-681b193f-006a-4186-8a43-c7da96cc88dd/mount"}
{"level":"info","ts":"2024-05-13T11:23:45Z","logger":"driver.node","msg":"NodeUnpublishVolume(fs) is succeeded","volume_id":"de6af941-057b-4ac3-a11c-392c427447e7","target_path":"/var/lib/kubelet/pods/5482ddf0-82be-4400-90cb-de85116f49d9/volumes/kubernetes.io~csi/pvc-681b193f-006a-4186-8a43-c7da96cc88dd/mount"}
{"level":"info","ts":"2024-05-13T11:28:28Z","msg":"start finalizing LogicalVolume","controller":"logicalvolume","controllerGroup":"topolvm.cybozu.com","controllerKind":"LogicalVolume","LogicalVolume":{"name":"pvc-681b193f-006a-4186-8a43-c7da96cc88dd"},"namespace":"","name":"pvc-681b193f-006a-4186-8a43-c7da96cc88dd","reconcileID":"6dd028f8-c13d-453d-bb62-5c1a8fad5cb6","name":"pvc-681b193f-006a-4186-8a43-c7da96cc88dd"}
{"level":"info","ts":"2024-05-13T11:28:28Z","msg":"invoking command","controller":"logicalvolume","controllerGroup":"topolvm.cybozu.com","controllerKind":"LogicalVolume","LogicalVolume":{"name":"pvc-681b193f-006a-4186-8a43-c7da96cc88dd"},"namespace":"","name":"pvc-681b193f-006a-4186-8a43-c7da96cc88dd","reconcileID":"6dd028f8-c13d-453d-bb62-5c1a8fad5cb6","args":["/usr/bin/nsenter","-m","-u","-i","-n","-p","-t","1","/sbin/lvm","vgs","topolvm-vg-ssd","-o","vg_uuid,vg_name,vg_size,vg_free","--units","b","--nosuffix","--reportformat","json"]}
{"level":"info","ts":"2024-05-13T11:28:28Z","msg":"invoking command","controller":"logicalvolume","controllerGroup":"topolvm.cybozu.com","controllerKind":"LogicalVolume","LogicalVolume":{"name":"pvc-681b193f-006a-4186-8a43-c7da96cc88dd"},"namespace":"","name":"pvc-681b193f-006a-4186-8a43-c7da96cc88dd","reconcileID":"6dd028f8-c13d-453d-bb62-5c1a8fad5cb6","args":["/usr/bin/nsenter","-m","-u","-i","-n","-p","-t","1","/sbin/lvm","lvremove","-f","topolvm-vg-ssd/de6af941-057b-4ac3-a11c-392c427447e7"]}
{"level":"info","ts":"2024-05-13T11:28:28Z","msg":"Logical volume \"de6af941-057b-4ac3-a11c-392c427447e7\" successfully removed","controller":"logicalvolume","controllerGroup":"topolvm.cybozu.com","controllerKind":"LogicalVolume","LogicalVolume":{"name":"pvc-681b193f-006a-4186-8a43-c7da96cc88dd"},"namespace":"","name":"pvc-681b193f-006a-4186-8a43-c7da96cc88dd","reconcileID":"6dd028f8-c13d-453d-bb62-5c1a8fad5cb6"}
{"level":"info","ts":"2024-05-13T11:28:28Z","msg":"removed a LV","controller":"logicalvolume","controllerGroup":"topolvm.cybozu.com","controllerKind":"LogicalVolume","LogicalVolume":{"name":"pvc-681b193f-006a-4186-8a43-c7da96cc88dd"},"namespace":"","name":"pvc-681b193f-006a-4186-8a43-c7da96cc88dd","reconcileID":"6dd028f8-c13d-453d-bb62-5c1a8fad5cb6","name":"de6af941-057b-4ac3-a11c-392c427447e7","name":"de6af941-057b-4ac3-a11c-392c427447e7"}
{"level":"info","ts":"2024-05-13T11:28:28Z","msg":"removed LV","controller":"logicalvolume","controllerGroup":"topolvm.cybozu.com","controllerKind":"LogicalVolume","LogicalVolume":{"name":"pvc-681b193f-006a-4186-8a43-c7da96cc88dd"},"namespace":"","name":"pvc-681b193f-006a-4186-8a43-c7da96cc88dd","reconcileID":"6dd028f8-c13d-453d-bb62-5c1a8fad5cb6","name":"pvc-681b193f-006a-4186-8a43-c7da96cc88dd","uid":"de6af941-057b-4ac3-a11c-392c427447e7"}
{"level":"info","ts":"2024-05-13T11:29:07Z","logger":"driver.node","msg":"NodePublishVolume called","volume_id":"de6af941-057b-4ac3-a11c-392c427447e7","publish_context":null,"target_path":"/var/lib/kubelet/pods/1bea3cf2-982e-43ad-95e2-ac8bb3312387/volumes/kubernetes.io~csi/pvc-681b193f-006a-4186-8a43-c7da96cc88dd/mount","volume_capability":"mount:<fs_type:\"ext4\" > access_mode:<mode:SINGLE_NODE_WRITER > ","read_only":false,"num_secrets":0,"volume_context":{"csi.storage.k8s.io/ephemeral":"false","csi.storage.k8s.io/pod.name":"kafka02-0","csi.storage.k8s.io/pod.namespace":"wynnbet-ma","csi.storage.k8s.io/pod.uid":"1bea3cf2-982e-43ad-95e2-ac8bb3312387","csi.storage.k8s.io/serviceAccount.name":"kafka-cluster","storage.kubernetes.io/csiProvisionerIdentity":"1711674431379-5732-topolvm.cybozu.com"}}

check PV status

kubectl get pv pvc-681b193f-006a-4186-8a43-c7da96cc88d
Error from server (NotFound): persistentvolumes "pvc-681b193f-006a-4186-8a43-c7da96cc88d" not found

descale kafka sts to replica 1 and check pod status

 kubectl get pod kafka02-0 
NAME        READY   STATUS     RESTARTS   AGE
kafka02-0   0/1     Init:0/2   0          18m

kubectl describe pod kafka02-0
Events:
  Type     Reason       Age                 From               Message
  ----     ------       ----                ----               -------
  Normal   Scheduled    19m                 default-scheduler  Successfully assigned wynnbet-ma/kafka02-0 to b2b-stage-hw4105
  Warning  FailedMount  99s (x8 over 17m)   kubelet            Unable to attach or mount volumes: unmounted volumes=[kafka-persistent-storage], unattached volumes=[], failed to process volumes=[]: timed out waiting for the condition
  Warning  FailedMount  58s (x17 over 19m)  kubelet            MountVolume.SetUp failed for volume "pvc-681b193f-006a-4186-8a43-c7da96cc88dd" : rpc error: code = Unknown desc = VolumeID is not found

[llamerada-jp]

The upgrade was kubernetes cluster upgrade only to the next minor version.

The node resource may have been re-created as a result of this operation. Could you check the creation timestamp of the node resource to see what happened?

Could you please clarify who is responsilbe for PVC deletion, if topolvm doesn't handle PVC directly?

If the node resource was re-created, TopoLVM's node finalize process delete PVC. So you should disable nodeFinalize feature as you pointed out.

Will nodeFinalize help?

controller:
  nodeFinalize:
   skipped: true

[jurim76]

The k8s upgrade was performed without node drain for worker nodes.
Seems node creation timestamp has not changed.

creationTimestamp: "2022-07-28T13:38:10Z

[llamerada-jp]

The k8s upgrade was performed without node drain for worker nodes.
Seems node creation timestamp has not changed.

Hmm, It doesn't seem to be TopoLVM's node finalization process.

I am concerned if this is a normal deletion process because an error is recorded in the your log. Could you find DeleteVolume logs for de6af941-057b-4ac3-a11c-392c427447e7 in topolvm-controller? Is it all of topolvm-node logs for pvc-681b193f-006a-4186-8a43-c7da96cc88dd or de6af941-057b-4ac3-a11c-392c427447e7(volume id)? I expect NodeUnpublishVolume log before the first start finalizing LogicalVolume message, could you find it? If you find any, would you please present those logs as well? And could you please check if a LogicalVolume resource with the same name as the PV having deletionTimestamp exists?

Apart from the above, something other than TopoLVM may have triggered the deletion. If your system records audit logs of api server, could you check what service account was used for deleting PV/PVC?

[jurim76]

Not sure about normal deletion process, because PVs and PVCs are not in terminated state.
Will try to collect more info

[jurim76]

I've found some misconfiguration during topolvm chart upgrade, when chart was upgraded with default "useLegacy=false", after that the chart was redeployed with correct "useLegacy=true".
According to this article

Since it is not possible to change the above fields of the PersistentVolume resource, it is necessary to recreate the resource when migrating the group name. Also, if .spec.persistentVolumeReclaimPolicy = Delete is set, there is a risk of deleting the actual LVM volume, so it is recommended to temporarily change it to Retain and then delete it.

Could changing topolvm.cybozu.com to topolvm.io trigger mass LVs deletion?

[llamerada-jp]

I have not checked, but it will likely be removed.

If you change the useLegacy flag, the resource name in the CRD also will be changed. If the old CRD is deleted when updated, the LogicalVolume resources are also deleted, so the LV will also be deleted.
In addition to the above, the records of csidrivers.storage.k8s.io and csinodes.storage.k8s.io are modified. This may cause the deletion process to be called. This is an uncertain expectation since I have not checked the behavior of k8s.

[jurim76]

Thank you for your clarification!