Failed to find logical volume messages in SMlog and defunct processes

[sniperkitten]

Hello!

Recently I noticed many defunct processes on xenserver after executing NAUBackup

root 31292 807 0 Jun25 ? 00:00:00 [LVMSR] <defunct> root 31331 807 0 Jun25 ? 00:00:00 [LVMSR] <defunct> root 31351 807 0 07:12 ? 00:00:00 [LVMSR] <defunct> root 31370 807 0 Jun25 ? 00:00:00 [LVMSR] <defunct> root 31401 807 0 02:40 ? 00:00:00 [LVMSR] <defunct> root 31523 807 0 04:07 ? 00:00:00 [LVMSR] <defunct> root 31574 807 0 02:52 ? 00:00:00 [LVMSR] <defunct> root 31577 807 0 Jun25 ? 00:00:00 [LVMSR] <defunct>

They all have same parent:

root 807 1 0 Jun25 ? 00:04:45 /usr/bin/python /opt/xensource/sm/LVMSR <methodCall><methodName>vdi_delete</methodName><params><param><value><struct><me root 862 807 0 Jun25 ? 00:00:00 [LVMSR] <defunct>

Found following errors in SMlog:

Jun 25 13:15:28 xenserver-enginatics1 SM: [27322] FAILED in util.pread: (rc 5) stdout: '', stderr: ' Failed to find logical volume "VG_XenStorage-bac4ccac-5680-915a-6f84-b975379aaa1c/cc4d186a-1846-47eb-9dcb-ea48bccd6d85.cbtlog" Jun 25 13:15:28 xenserver-enginatics1 SM: [27322] ' Jun 25 13:15:28 xenserver-enginatics1 SM: [27322] Ignoring exception for LV check: /dev/VG_XenStorage-bac4ccac-5680-915a-6f84-b975379aaa1c/cc4d186a-1846-47eb-9dcb-ea48bccd6d85.cbtlog ! Jun 25 13:20:31 xenserver-enginatics1 SM: [30686] FAILED in util.pread: (rc 5) stdout: '', stderr: ' Failed to find logical volume "VG_XenStorage-bac4ccac-5680-915a-6f84-b975379aaa1c/71494603-83b2-403f-83cc-329cadce9d6f.cbtlog" Jun 25 13:20:31 xenserver-enginatics1 SM: [30686] ' Jun 25 13:20:31 xenserver-enginatics1 SM: [30686] Ignoring exception for LV check: /dev/VG_XenStorage-bac4ccac-5680-915a-6f84-b975379aaa1c/71494603-83b2-403f-83cc-329cadce9d6f.cbtlog ! Jun 25 15:12:23 xenserver-enginatics1 SM: [666] FAILED in util.pread: (rc 5) stdout: '', stderr: ' Failed to find logical volume "VG_XenStorage-bac4ccac-5680-915a-6f84-b975379aaa1c/cc4d186a-1846-47eb-9dcb-ea48bccd6d85.cbtlog" Jun 25 15:12:23 xenserver-enginatics1 SM: [666] ' Jun 25 15:12:23 xenserver-enginatics1 SM: [666] Ignoring exception for LV check: /dev/VG_XenStorage-bac4ccac-5680-915a-6f84-b975379aaa1c/cc4d186a-1846-47eb-9dcb-ea48bccd6d85.cbtlog ! Jun 25 15:12:23 xenserver-enginatics1 SM: [855] FAILED in util.pread: (rc 5) stdout: '', stderr: ' Failed to find logical volume "VG_XenStorage-bac4ccac-5680-915a-6f84-b975379aaa1c/71494603-83b2-403f-83cc-329cadce9d6f.cbtlog" Jun 25 15:12:23 xenserver-enginatics1 SM: [855] ' Jun 25 15:12:23 xenserver-enginatics1 SM: [855] Ignoring exception for LV check: /dev/VG_XenStorage-bac4ccac-5680-915a-6f84-b975379aaa1c/71494603-83b2-403f-83cc-329cadce9d6f.cbtlog !

Following messages taken from NAUBackup log with same VDI IDs:

2019-06-25-(15:12:22) - The following items are about to be destroyed 2019-06-25-(15:12:22) - VM : 2a0bc086-1ef0-f404-3660-a58b83573c6d (RESTORE_EBS r1213a) 2019-06-25-(15:12:22) - VDI: cc4d186a-1846-47eb-9dcb-ea48bccd6d85 (EBS r1213a upgraded OEL 6 root "/" mountpoint) 2019-06-25-(15:12:22) - VDI: 71494603-83b2-403f-83cc-329cadce9d6f (EBS r1213a upgraded OEL 6 /d01 EBS mountpoint)

Xen Server and Xen SDK version: 8.0
NAUBackup version: V3.24

Please help me with the investigation.

Thank you!

[NAUbackup]

Did you check to see if the snapshots were correctly removed after the backup process completed?
Unfortunately, I have not had a chance to test this thoroughly yet on an 8.0 installation. Did you see anything like this under XS 7.X?

[sniperkitten]

Hi Checked snapshots in Xen Center - they were removed correctly. I didn't happen in XenServer 7.6, we upgraded at the beginning of this month to 8.0.

…

On Wed, 26 Jun 2019 at 19:00, NAUbackup ***@***.***> wrote: Did you check to see if the snapshots were correctly removed after the backup process completed? Unfortunately, I have not had a chance to test this thoroughly yet on an 8.0 installation. Did you see anything like this under XS 7.X? — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub <#91?email_source=notifications&email_token=AINTJENJFULR6S4DFYFRSDTP4OHCZA5CNFSM4H3PN5M2YY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGODYUAGOI#issuecomment-505938745>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AINTJEJV7GRXX46IZODFDSDP4OHCZANCNFSM4H3PN5MQ> .

[NAUbackup]

Not sure how such an LVM call would have been initiated via VmBackup to result in this. I will try to get a test instance running soon under 8.0 and see if I can replicate this. Sorry this is showing up. Is everything functional otherwise?

[sniperkitten]

Yes, everything else seems to be working fine.
Backups finish successfully regardless of this issue.
I restored one of the VMs from such recent backup and it started normally.

[sniperkitten]

Hi

Today after number of zombie processes reached 10 000, I killed their parent and it worked as workaround - all zombies disappeared. Here's the process I killed:

root 807 1 0 Jun25 ? 00:44:32 /usr/bin/python /opt/xensource/sm/LVMSR <methodCall><methodName>vdi_delete</methodName><params><param><value><struct><member><name>host_ref</name><value>OpaqueRef:11a4f521-1bcb-4852-9218-444fadda3540</value></member><member><name>command</name><value>vdi_delete</value></member><member><name>args</name><value><array><data/></array></value></member><member><name>device_config</name><value><struct><member><name>SRmaster</name><value>true</value></member><member><name>device</name><value>/dev/disk/by-id/ata-Micron_5200_MTFDDAK3T8TDC_18531FF5401F</value></member></struct></value></member><member><name>session_ref</name><value>OpaqueRef:5aa061c5-eeda-485d-8786-820f56a6e90e</value></member><member><name>sr_ref</name><value>OpaqueRef:3c102b39-623d-4ee1-8065-4f5e4153d3af</value></member><member><name>sr_uuid</name><value>bac4ccac-5680-915a-6f84-b975379aaa1c</value></member><member><name>vdi_ref</name><value>OpaqueRef:7b5c22d8-6a75-4f55-b1db-387e967aaa3a</value></member><member><name>vdi_location</name><value>cc4d186a-1846-47eb-9dcb-ea48bccd6d85</value></member><member><name>vdi_uuid</name><value>cc4d186a-1846-47eb-9dcb-ea48bccd6d85</value></member><member><name>subtask_of</name><value>DummyRef:|7a421cce-426e-4034-a7b9-7d8f2b194932|VDI.destroy</value></member><member><name>vdi_on_boot</name><value>persist</value></member><member><name>vdi_allow_caching</name><value>false</value></member></struct></value></param></params></methodCall>

[NAUbackup]

Seems that the parent process doesn't terminate normally, and exacerbated the issue. Would be curious if the same thing happens if you run another backup process. I do not see anything like this under 7.X, hence it is clearly related to changes in 8.0.

[sniperkitten]

Hi

Reproduced issue after getting rid of zombie processes.
First backup completed normally, so I initiated the second.
Snapshot got deleted successfully, still this process left hanging along with its childs:

root 18663 1 0 08:43 ? 00:00:04 /usr/bin/python /opt/xensource/sm/LVMSR <methodCall><methodName>vdi_delete</methodName><params><param><value><struct><member><name>host_ref</name><value>OpaqueRef:11a4f521-1bcb-4852-9218-444fadda3540</value></member><member><name>command</name><value>vdi_delete</value></member><member><name>args</name><value><array><data/></array></value></member><member><name>device_config</name><value><struct><member><name>SRmaster</name><value>true</value></member><member><name>device</name><value>/dev/disk/by-id/ata-Micron_5200_MTFDDAK3T8TDC_18531FF5401F</value></member></struct></value></member><member><name>session_ref</name><value>OpaqueRef:5e3e4027-3a05-4ff6-889d-4d1f9fb2b79b</value></member><member><name>sr_ref</name><value>OpaqueRef:3c102b39-623d-4ee1-8065-4f5e4153d3af</value></member><member><name>sr_uuid</name><value>bac4ccac-5680-915a-6f84-b975379aaa1c</value></member><member><name>vdi_ref</name><value>OpaqueRef:06fa189d-1500-4bae-a008-3d1ad0a11b57</value></member><member><name>vdi_location</name><value>03d9f8ee-43b9-4583-bf42-0194a86acbe3</value></member><member><name>vdi_uuid</name><value>03d9f8ee-43b9-4583-bf42-0194a86acbe3</value></member><member><name>subtask_of</name><value>DummyRef:|53937de2-c14b-4ed4-bb20-1a93802e371f|VDI.destroy</value></member><member><name>vdi_on_boot</name><value>persist</value></member><member><name>vdi_allow_caching</name><value>false</value></member></struct></value></param></params></methodCall> root 19245 18663 0 09:01 ? 00:00:00 [LVMSR] <defunct> root 21032 18663 0 09:02 ? 00:00:00 [LVMSR] <defunct>

Killed it again and zombie processes disappeared also.

[sniperkitten]

Hi

Please tell is there any news?

Thank you

[NAUbackup]

I am having issues getting the NFS network connected to my tests servers and need to work with out network operations group. Until that's rectified, I won't have a CH 8.0 system I can test with. Sorry it's taking this long.

[BogdanRudas]

We are using own backup scripts to exports VM snapsots, but faced same issue.
Snapshots looks deleted from Xencenters, but LVMSR space is not freed.
This apply to Xenserver XS71ECU2015 and most probably to Hypervisor 8. We have no evidences of this in XCP-ng 7.6 (but probably need to deploy XCP-ng 8 or just update our's 7.6 which are not as big a installation of licensed Citrix products)

[NAUbackup]

Make sure you don't have too many snapshots already and there is enough room to be able to take an additional snapshot. If the SR is too full, the coalesce process will sometimes also fail to work. You can try manually rescanning the SR, or go and delete snapshots manually first to ensure there is enough free space. Worst case you may have to shuffle VMs around to free up some space and also potentially force the coalescing to kick in.

[BogdanRudas]

I know about such restrictions. In may case I have at least triple of VM size free on that SR.
Process tree looks like.

systemd --switched-root --system --deserialize 21
|-LVMSR /opt/xensource/sm/LVMSRvdi_deleteh
| |-(LVMSR)
| |-(LVMSR)
| |-(LVMSR)
| |-(LVMSR)
| |-(LVMSR)
| |-(LVMSR)
| |-(LVMSR)
| |-(LVMSR)
| |-(LVMSR)
| |-(LVMSR)
| |-(LVMSR)
| |-(LVMSR)
| |-(LVMSR)
| |-(LVMSR)
| |-(LVMSR)
| |-(LVMSR)
| |-(LVMSR)
| |-(LVMSR)

Looking through our monitoring, it seems that the issue was caused by some update that I've applied on Xenserver 7.1 before July 28th. Since that time it triggering alerts from time to time and max number of processes I've seen in monitoring was 3k+ (and I don't finished monitoring check yet). I submited a case to Citrix. Once I killed that parent process and all zombies disappeared.
I'm sorry for discussing this here, but I think it is Xenserver issue and not related to NAUbackup itself.

[sniperkitten]

Thank you for feedback, Bogdan!
Really looks like Xenserver problem.
Can you please share solution from Citrix if they manage to resolve it.

[sniperkitten]

Bogdan, did you find a way to manually free space as a workaround? If yes, please share, Thank you

[BogdanRudas]

There are two ways:

1. Gracefully move all VMs using Storage Xenmotion to other host, reboot, do sr_scan.
2. See pstree, kill parrent LVMSR vdi_delete process, then zmobies disappears and finally do sr_scan. I'm unsure it this way is safe, but it worked for me while ago.

Finally you have a look of xe vdi-list and clean up orgphaed VDI. There are many discussion about this in Google and especially on Citrix forums.