The problem here is not that vdsm failed deleting the LV, that is a coincidence due to the VM running on the same host as SPM.
The problem here is that engine is instructing vdsm to delete it while the VM is still writing to it.
engine should not try to delete the volume until it is absolutely sure the VM is running on only the source disk.
Created attachment 745687 [details] logs Description of problem: I ran a vm on hsm and restarted the vdsm on the spm during dataSync step of LSM. we try to rollback and fail on deleteImage because lvchange fails on device busy by qemu-kvm. Version-Release number of selected component (if applicable): sf15 vdsm-4.10.2-17.0.el6ev.x86_64 How reproducible: 100% Steps to Reproduce: 1. in iscsi storage with two hosts run a vm created from template on the hsm host 2. start LSM on the vm's disk 3. restart vdsm on spm during dataSync step Actual results: we rollback but fail to remove the lv because lvchange fails on device busy. running lsof we can see that it's qemu-kvm that's still using the lv Expected results: we should be able to remove the lv (lvchange should succeed). Additional info: full logs [root@gold-vdsd ~]# lvs LV VG Attr LSize Pool Origin Data% Move Log Cpy%Sync Convert d64b9ac6-dda6-433a-9d78-33656df1a3b7 38755249-4bb3-4841-bf5b-05f4a521514d -wi------ 5.00g e886fb6e-f91f-46ae-a488-0f24e47f5731 38755249-4bb3-4841-bf5b-05f4a521514d -wi------ 2.00g ids 38755249-4bb3-4841-bf5b-05f4a521514d -wi-ao--- 128.00m inbox 38755249-4bb3-4841-bf5b-05f4a521514d -wi-a---- 128.00m leases 38755249-4bb3-4841-bf5b-05f4a521514d -wi-a---- 2.00g master 38755249-4bb3-4841-bf5b-05f4a521514d -wi-ao--- 1.00g metadata 38755249-4bb3-4841-bf5b-05f4a521514d -wi-a---- 512.00m outbox 38755249-4bb3-4841-bf5b-05f4a521514d -wi-a---- 128.00m d64b9ac6-dda6-433a-9d78-33656df1a3b7 81ef11d0-4c0c-47b4-8953-d61a6af442d8 -wi------ 5.00g d6689c9c-0a94-4d52-9582-30168d569922 81ef11d0-4c0c-47b4-8953-d61a6af442d8 -wi-ao--- 3.00g e886fb6e-f91f-46ae-a488-0f24e47f5731 81ef11d0-4c0c-47b4-8953-d61a6af442d8 -wi-a---- 2.00g ids 81ef11d0-4c0c-47b4-8953-d61a6af442d8 -wi-ao--- 128.00m inbox 81ef11d0-4c0c-47b4-8953-d61a6af442d8 -wi-a---- 128.00m leases 81ef11d0-4c0c-47b4-8953-d61a6af442d8 -wi-a---- 2.00g master 81ef11d0-4c0c-47b4-8953-d61a6af442d8 -wi-a---- 1.00g metadata 81ef11d0-4c0c-47b4-8953-d61a6af442d8 -wi-a---- 512.00m outbox 81ef11d0-4c0c-47b4-8953-d61a6af442d8 -wi-a---- 128.00m d64b9ac6-dda6-433a-9d78-33656df1a3b7 d326916a-89b6-41c8-9c14-4b9cf8a1c979 -wi------ 5.00g d6689c9c-0a94-4d52-9582-30168d569922 d326916a-89b6-41c8-9c14-4b9cf8a1c979 -wi-ao--- 3.00g da9e81d1-d992-4b2f-ba36-e8f9fb0a48c1 d326916a-89b6-41c8-9c14-4b9cf8a1c979 -wi-ao--- 1.00g e886fb6e-f91f-46ae-a488-0f24e47f5731 d326916a-89b6-41c8-9c14-4b9cf8a1c979 -wi-ao--- 2.00g ids d326916a-89b6-41c8-9c14-4b9cf8a1c979 -wi-ao--- 128.00m inbox d326916a-89b6-41c8-9c14-4b9cf8a1c979 -wi-a---- 128.00m leases d326916a-89b6-41c8-9c14-4b9cf8a1c979 -wi-a---- 2.00g master d326916a-89b6-41c8-9c14-4b9cf8a1c979 -wi-a---- 1.00g metadata d326916a-89b6-41c8-9c14-4b9cf8a1c979 -wi-a---- 512.00m outbox d326916a-89b6-41c8-9c14-4b9cf8a1c979 -wi-a---- 128.00m lv_root vg0 -wi-ao--- 120.79g lv_swap vg0 -wi-ao--- 15.74g [root@gold-vdsd ~]# !less less /var/log/vdsm/vdsm.log [root@gold-vdsd ~]# lsof /dev/81ef11d0-4c0c-47b4-8953-d61a6af442d8/d6689c9c-0a94-4d52-9582-30168d569922 COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME qemu-kvm 9047 qemu 10u BLK 253,52 0x40000000 10677932 /dev/81ef11d0-4c0c-47b4-8953-d61a6af442d8/../dm-52 [root@gold-vdsd ~]# Thread-305::DEBUG::2013-05-09 17:28:46,471::misc::83::Storage.Misc.excCmd::(<lambda>) FAILED: <err> = ' WARNING: This metadata update is NOT backed up\n device-mapper: remove ioctl on failed: Device or resource busy\n device-mapper: remove ioctl on failed: Device or resource busy\n device-mapper: remove ioctl on failed: Device or resource busy\n device-mapper: remove ioctl on failed: Device or resource busy\n device-mapper: remove ioctl on failed: Device or resource busy\n device-mapper: remove ioctl on failed: Device or resource busy\n device-mapper: remove ioctl on failed: Device or resource busy\n device-mapper: remove ioctl on failed: Device or resource busy\n device-mapper: remove ioctl on failed: Device or resource busy\n device-mapper: remove ioctl on failed: Device or resource busy\n device-mapper: remove ioctl on failed: Device or resource busy\n device-mapper: remove ioctl on failed: Device or resource busy\n device-mapper: remove ioctl on failed: Device or resource busy\n device-mapper: remove ioctl on failed: Device or resource busy\n device-mapper: remove ioctl on failed: Device or resource busy\n device-mapper: remove ioctl on failed: Device or resource busy\n device-mapper: remove ioctl on failed: Device or resource busy\n device-mapper: remove ioctl on failed: Device or resource busy\n device-mapper: remove ioctl on failed: Device or resource busy\n device-mapper: remove ioctl on failed: Device or resource busy\n device-mapper: remove ioctl on failed: Device or resource busy\n device-mapper: remove ioctl on failed: Device or resource busy\n device-mapper: remove ioctl on failed: Device or resource busy\n device-mapper: remove ioctl on failed: Device or resource busy\n device-mapper: remove ioctl on failed: Device or resource busy\n Unable to deactivate 81ef11d0--4c0c--47b4--8953--d61a6af442d8-d6689c9c--0a94--4d52--9582--30168d569922 (253:52)\n Unable to deactivate logical volume "d6689c9c-0a94-4d52-9582-30168d569922"\n'; <rc> = 5 Thread-305::DEBUG::2013-05-09 17:28:46,477::lvm::498::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' got the operation mutex Thread-305::DEBUG::2013-05-09 17:28:46,478::lvm::510::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' released the operation mutex Thread-305::ERROR::2013-05-09 17:28:46,478::task::850::TaskManager.Task::(_setError) Task=`c2a855b0-aa21-4b91-bc3a-1679188cebbc`::Unexpected error Traceback (most recent call last): File "/usr/share/vdsm/storage/task.py", line 857, in _run return fn(*args, **kargs) File "/usr/share/vdsm/logUtils.py", line 41, in wrapper res = f(*args, **kwargs) File "/usr/share/vdsm/storage/hsm.py", line 1474, in deleteImage dom.deleteImage(sdUUID, imgUUID, volsByImg) File "/usr/share/vdsm/storage/blockSD.py", line 974, in deleteImage deleteVolumes(sdUUID, toDel) File "/usr/share/vdsm/storage/blockSD.py", line 182, in deleteVolumes lvm.removeLVs(sdUUID, vols) File "/usr/share/vdsm/storage/lvm.py", line 1063, in removeLVs raise se.CannotRemoveLogicalVolume(vgName, str(lvNames)) CannotRemoveLogicalVolume: Cannot remove Logical Volume: ('81ef11d0-4c0c-47b4-8953-d61a6af442d8', "{'da9e81d1-d992-4b2f-ba36-e8f9fb0a48c1': ImgsPar(imgs=['e322e29b-221a-4a44-b182-fd0d74a126c7'], parent='e886fb6e-f91f-46ae-a488-0f24e47f5731'), 'd6689c9c-0a94-4d52-9582-30168d569922': ImgsPar(imgs=['e322e29b-221a-4a44-b182-fd0d74a126c7'], parent='da9e81d1-d992-4b2f-ba36-e8f9fb0a48c1')}") Thread-305::DEBUG::2013-05-09 17:28:46,483::task::869::TaskManager.Task::(_run) Task=`c2a855b0-aa21-4b91-bc3a-1679188cebbc`::Task._run: c2a855b0-aa21-4b91-bc3a-1679188cebbc ('81ef11d0-4c0c-47b4-8953-d61a6af442d8', '7fd33b43-a9f4-4eb7-a885-e9583a929ceb', 'e322e29b-221a-4a44-b182-fd0d74a126c7', 'false', 'false') {} failed - stopping task [root@gold-vdsd ~]# ps -elf |grep qemu 6 S qemu 9047 1 3 80 0 - 288285 poll_s 17:25 ? 00:01:43 /usr/libexec/qemu-kvm -name DSK -S -M rhel6.4.0 -cpu Nehalem -enable-kvm -m 512 -smp 1,sockets=1,cores=1,threads=1 -uuid 362bee65-f875-46a4-87d6-7e6db89dd7a2 -smbios type=1,manufacturer=Red Hat,product=RHEV Hypervisor,version=6Server-6.4.0.4.el6,serial=5e1cf2d7-00cd-4796-9c29-cb4bc2c0a2fa,uuid=362bee65-f875-46a4-87d6-7e6db89dd7a2 -nodefconfig -nodefaults -chardev socket,id=charmonitor,path=/var/lib/libvirt/qemu/DSK.monitor,server,nowait -mon chardev=charmonitor,id=monitor,mode=control -rtc base=2013-05-09T14:25:54,driftfix=slew -no-shutdown -device piix3-usb-uhci,id=usb,bus=pci.0,addr=0x1.0x2 -device virtio-serial-pci,id=virtio-serial0,bus=pci.0,addr=0x5 -drive file=/rhev/data-center/7fd33b43-a9f4-4eb7-a885-e9583a929ceb/d326916a-89b6-41c8-9c14-4b9cf8a1c979/images/e322e29b-221a-4a44-b182-fd0d74a126c7/da9e81d1-d992-4b2f-ba36-e8f9fb0a48c1,if=none,id=drive-ide0-0-0,format=qcow2,serial=e322e29b-221a-4a44-b182-fd0d74a126c7,cache=none,werror=stop,rerror=stop,aio=native -device ide-drive,bus=ide.0,unit=0,drive=drive-ide0-0-0,id=ide0-0-0,bootindex=1 -drive if=none,media=cdrom,id=drive-ide0-1-0,readonly=on,format=raw,serial= -device ide-drive,bus=ide.1,unit=0,drive=drive-ide0-1-0,id=ide0-1-0 -netdev tap,fd=26,id=hostnet0,vhost=on,vhostfd=27 -device virtio-net-pci,netdev=hostnet0,id=net0,mac=00:1a:4a:23:a1:b1,bus=pci.0,addr=0x3 -chardev socket,id=charchannel0,path=/var/lib/libvirt/qemu/channels/DSK.com.redhat.rhevm.vdsm,server,nowait -device virtserialport,bus=virtio-serial0.0,nr=1,chardev=charchannel0,id=channel0,name=com.redhat.rhevm.vdsm -chardev socket,id=charchannel1,path=/var/lib/libvirt/qemu/channels/DSK.org.qemu.guest_agent.0,server,nowait -device virtserialport,bus=virtio-serial0.0,nr=2,chardev=charchannel1,id=channel1,name=org.qemu.guest_agent.0 -chardev spicevmc,id=charchannel2,name=vdagent -device virtserialport,bus=virtio-serial0.0,nr=3,chardev=charchannel2,id=channel2,name=com.redhat.spice.0 -spice port=5900,tls-port=5901,addr=0,x509-dir=/etc/pki/vdsm/libvirt-spice,tls-channel=main,tls-channel=display,tls-channel=inputs,tls-channel=cursor,tls-channel=playback,tls-channel=record,tls-channel=smartcard,tls-channel=usbredir,seamless-migration=on -k en-us -vga qxl -global qxl-vga.ram_size=67108864 -global qxl-vga.vram_size=67108864 -device intel-hda,id=sound0,bus=pci.0,addr=0x4 -device hda-duplex,id=sound0-codec0,bus=sound0.0,cad=0 0 S root 16265 22167 0 80 0 - 25812 pipe_w 18:12 pts/0 00:00:00 grep qemu