Re: [ovirt-users] Simple way to activate live merge in FC20 cluster

On Thu, Nov 20, 2014 at 8:13 PM, Markus Stockhausen <stockhausen(a)collogia.de [snip] Hello, following the flow, as I have now an all-in-one environment based on F20 and oVirt 3.5. As it is both my engine and my hypervisor, I should be in the best situation.... live merge is supposed to be supported on file based storage, that should match what I have (local on Host). In fact, installing oVirt AIO on F20 automatically gives the virt-preview repo through the ovirt-3.5-dependencies.repo file and I see: [root@tekkaman qemu]# rpm -q libvirt libvirt-1.2.9.1-1.fc20.x86_64 [root@tekkaman qemu]# vdsClient -s 0 getVdsCaps | grep -i merge liveMerge = 'true' [root@tekkaman qemu]# rpm -q qemu qemu-1.6.2-10.fc20.x86_64 Created a CentOS 7 x86_64 VM with a VirtIO-SCSI disk and after install I powered off and run it normally. Then I took a snapshot (while VM powered on) and then ran a yum update. At the end I reboot the VM with the new kernel installed and tried to delete the snapshot and the task indeed started: Snapshot 'test per live merge' deletion for VM 'c7' was initiated by admin. but about a minute later I got error: Failed to delete snapshot 'test per live merge' for VM 'c7'. here below relevant parts in log files. What did I miss in the workflow? BTW: both during the live snapshot and during the live merge I got disconnected both from spice console and from an ssh session open into VM (I could reconnect on both): is this expected? I hope not so.. Gianluca engine.log 2014-11-21 01:16:00,182 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (pool-7-thread-3) [3337208b] Failed in MergeVDS method 2014-11-21 01:16:00,183 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (pool-7-thread-3) [3337208b] Command org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand return value StatusOnlyReturnForXmlRpc [mStatus=StatusForXmlRpc [mCode=52, mMessage=Merge failed]] 2014-11-21 01:16:00,184 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (pool-7-thread-3) [3337208b] HostName = local_host 2014-11-21 01:16:00,190 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (pool-7-thread-3) [3337208b] Command MergeVDSCommand(HostName = local_host, MergeVDSCommandParameters{HostId = aab9571f-da17-4c3c-9e6b-d0224b84c31e, vmId=0ba6a56b-542c-480e-8bab-88aea9195302, storagePoolId=65c9777e-23f1-4f04-8cea-e7c8871dc88b, storageDomainId=0a8035e6-e41d-40ff-a154-e0a374f264b2, imageGroupId=8a0ba67f-78c0-4ded-9bda-97bb9424e385, imageId=1fdc7440-2465-49ec-8368-141afc0721f1, baseImageId=cd7dd270-0895-411d-bc97-c5ad0ebd80b1, topImageId=1fdc7440-2465-49ec-8368-141afc0721f1, bandwidth=0}) execution failed. Exception: VDSErrorException: VDSGenericException: VDSErrorException: Failed to MergeVDS, error = Merge failed, code = 52 2014-11-21 01:16:00,191 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (pool-7-thread-3) [3337208b] FINISH, MergeVDSCommand, log id: 70748b53 2014-11-21 01:16:00,192 ERROR [org.ovirt.engine.core.bll.MergeCommand] (pool-7-thread-3) [3337208b] Command org.ovirt.engine.core.bll.MergeCommand throw Vdc Bll exception. With error message VdcBLLException: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorException: VDSGenericException: VDSErrorException: Failed to MergeVDS, error = Merge failed, code = 52 (Failed with error mergeErr and code 52) 2014-11-21 01:16:00,205 ERROR [org.ovirt.engine.core.bll.MergeCommand] (pool-7-thread-3) [3337208b] Transaction rolled-back for command: org.ovirt.engine.core.bll.MergeCommand. 2014-11-21 01:16:09,888 INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (DefaultQuartzScheduler_Worker-55) task id f245da80-58ce-4e2e-bb5a-0261cf71de0d is in pre-polling period and should not be polled. Pre-polling period is 60,000 millis. 2014-11-21 01:16:09,889 INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (DefaultQuartzScheduler_Worker-55) task id c7c363f1-98b8-468c-8fca-cf3116d00221 is in pre-polling period and should not be polled. Pre-polling period is 60,000 millis. 2014-11-21 01:16:10,080 ERROR [org.ovirt.engine.core.bll.RemoveSnapshotSingleDiskLiveCommand] (DefaultQuartzScheduler_Worker-56) [1457fcca] Failed child command status for step MERGE vdsm.log Thread-266::DEBUG::2014-11-21 01:16:00,144::resourceManager::641::Storage.ResourceManager::(releaseResource) Resource 'Storag e.0a8035e6-e41d-40ff-a154-e0a374f264b2' is free, finding out if anyone is waiting for it. Thread-266::DEBUG::2014-11-21 01:16:00,144::resourceManager::649::Storage.ResourceManager::(releaseResource) No one is waitin g for resource 'Storage.0a8035e6-e41d-40ff-a154-e0a374f264b2', Clearing records. Thread-266::DEBUG::2014-11-21 01:16:00,144::task::993::Storage.TaskManager.Task::(_decref) Task=`95f79027-3613-4f05-9d2d-02f8 c7975f02`::ref 0 aborting False Thread-266::INFO::2014-11-21 01:16:00,158::vm::5743::vm.Vm::(merge) vmId=`0ba6a56b-542c-480e-8bab-88aea9195302`::Starting mer ge with jobUUID='2247fea2-df73-407e-ad16-4622af7f52aa' Thread-266::DEBUG::2014-11-21 01:16:00,160::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 67 edom: 10 level: 2 message: unsupported configuration: active commit not supported with this QEMU binary Thread-266::ERROR::2014-11-21 01:16:00,161::vm::5751::vm.Vm::(merge) vmId=`0ba6a56b-542c-480e-8bab-88aea9195302`::Live merge failed (job: 2247fea2-df73-407e-ad16-4622af7f52aa) Traceback (most recent call last): File "/usr/share/vdsm/virt/vm.py", line 5747, in merge flags) File "/usr/share/vdsm/virt/vm.py", line 670, in f ret = attr(*args, **kwargs) File "/usr/lib/python2.7/site-packages/vdsm/libvirtconnection.py", line 111, in wrapper ret = f(*args, **kwargs) File "/usr/lib64/python2.7/site-packages/libvirt.py", line 638, in blockCommit if ret == -1: raise libvirtError ('virDomainBlockCommit() failed', dom=self) libvirtError: unsupported configuration: active commit not supported with this QEMU binary Thread-266::DEBUG::2014-11-21 01:16:00,181::BindingXMLRPC::1139::vds::(wrapper) return merge with {'status': {'message': 'Merge failed', 'code': 52}} ioprocess communication (4939)::DEBUG::2014-11-21 01:16:00,656::__init__::375::IOProcess::(_processLogs) (null)|Receiving request... ioprocess communication (4939)::DEBUG::2014-11-21 01:16:00,657::__init__::375::IOProcess::(_processLogs) (null)|Queuing request in the thread pool... Thread-26::DEBUG::2014-11-21 01:16:00,658::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd if=/rhev/data-center/mnt/_data_DATA2/b24b94c7-5935-4940-9152-36ecd370ba7c/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None) ioprocess communication (4939)::DEBUG::2014-11-21 01:16:00,659::__init__::375::IOProcess::(_processLogs) Extracting request information... ioprocess communication (4939)::DEBUG::2014-11-21 01:16:00,668::__init__::375::IOProcess::(_processLogs) (7100) Got request for method 'statvfs' ioprocess communication (4939)::DEBUG::2014-11-21 01:16:00,668::__init__::375::IOProcess::(_processLogs) (7100) Queuing response Thread-26::DEBUG::2014-11-21 01:16:00,687::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n588 bytes (588 B) copied, 0.020396 s, 28.8 kB/s\n'; <rc> = 0 ioprocess communication (4939)::DEBUG::2014-11-21 01:16:00,688::__init__::375::IOProcess::(_processLogs) (null)|Receiving request... ioprocess communication (4939)::DEBUG::2014-11-21 01:16:00,689::__init__::375::IOProcess::(_processLogs) (null)|Queuing request in the thread pool... ioprocess communication (4939)::DEBUG::2014-11-21 01:16:00,690::__init__::375::IOProcess::(_processLogs) Extracting request information... ioprocess communication (4939)::DEBUG::2014-11-21 01:16:00,690::__init__::375::IOProcess::(_processLogs) (7101) Got request for method 'statvfs' ioprocess communication (4939)::DEBUG::2014-11-21 01:16:00,691::__init__::375::IOProcess::(_processLogs) (7101) Queuing response ioprocess communication (4939)::DEBUG::2014-11-21 01:16:00,691::__init__::375::IOProcess::(_processLogs) (null)|Receiving request... ioprocess communication (4939)::DEBUG::2014-11-21 01:16:00,691::__init__::375::IOProcess::(_processLogs) Queuing request in the thread pool... ioprocess communication (4939)::DEBUG::2014-11-21 01:16:00,691::__init__::375::IOProcess::(_processLogs) Extracting request information... ioprocess communication (4939)::DEBUG::2014-11-21 01:16:00,692::__init__::375::IOProcess::(_processLogs) (null)|(7102) Got request for method 'access' ioprocess communication (4939)::DEBUG::2014-11-21 01:16:00,693::__init__::375::IOProcess::(_processLogs) (7102) Queuing response ioprocess communication (4939)::DEBUG::2014-11-21 01:16:00,693::__init__::375::IOProcess::(_processLogs) (null)|Receiving request... ioprocess communication (4939)::DEBUG::2014-11-21 01:16:00,693::__init__::375::IOProcess::(_processLogs) Queuing request in the thread pool... ioprocess communication (4939)::DEBUG::2014-11-21 01:16:00,694::__init__::375::IOProcess::(_processLogs) (null)|Extracting request information... ioprocess communication (4939)::DEBUG::2014-11-21 01:16:00,695::__init__::375::IOProcess::(_processLogs) (7103) Got request for method 'access' ioprocess communication (4939)::DEBUG::2014-11-21 01:16:00,695::__init__::375::IOProcess::(_processLogs) (7103) Queuing response ioprocess communication (4939)::DEBUG::2014-11-21 01:16:00,695::__init__::375::IOProcess::(_processLogs) (null)|Receiving req