Thread-110812::DEBUG::2012-04-26 10:14:11,538::resourceManager::562::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.524a7003-edec-4f52-a38e-b15cadfbe3ef', Clearing records.
Thread-110812::DEBUG::2012-04-26 10:14:11,538::task::980::TaskManager.Task::(_decref) Task=`2df4d0ae-084e-4d13-8098-6649ac5c7132`::ref 0 aborting False
Thread-110816::DEBUG::2012-04-26 10:14:17,886::task::588::TaskManager.Task::(_updateState) Task=`126cc9ca-241d-43a3-ac66-7f0d41c98352`::moving from state init -> state preparing
Thread-110816::INFO::2012-04-26 10:14:17,887::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-110816::INFO::2012-04-26 10:14:17,888::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00180697441101', 'lastCheck': 1335485552.219619, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00167393684387', 'lastCheck': 1335485555.818574, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00185298919678', 'lastCheck': 1335485555.817463, 'code': 0, 'valid': True}}
Thread-110816::DEBUG::2012-04-26 10:14:17,889::task::1174::TaskManager.Task::(prepare) Task=`126cc9ca-241d-43a3-ac66-7f0d41c98352`::finished: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00180697441101', 'lastCheck': 1335485552.219619, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00167393684387', 'lastCheck': 1335485555.818574, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00185298919678', 'lastCheck': 1335485555.817463, 'code': 0, 'valid': True}}
Thread-110816::DEBUG::2012-04-26 10:14:17,889::task::588::TaskManager.Task::(_updateState) Task=`126cc9ca-241d-43a3-ac66-7f0d41c98352`::moving from state preparing -> state finished
Thread-110816::DEBUG::2012-04-26 10:14:17,890::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-110816::DEBUG::2012-04-26 10:14:17,891::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-110816::DEBUG::2012-04-26 10:14:17,891::task::980::TaskManager.Task::(_decref) Task=`126cc9ca-241d-43a3-ac66-7f0d41c98352`::ref 0 aborting False
Thread-110819::DEBUG::2012-04-26 10:14:21,632::clientIF::261::Storage.Dispatcher.Protect::(wrapper) [172.30.0.229]
Thread-110819::DEBUG::2012-04-26 10:14:21,634::task::588::TaskManager.Task::(_updateState) Task=`9023ebe8-4202-4119-bb8d-5ad9b1584652`::moving from state init -> state preparing
Thread-110819::INFO::2012-04-26 10:14:21,635::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='524a7003-edec-4f52-a38e-b15cadfbe3ef', options=None)
Thread-110819::INFO::2012-04-26 10:14:21,636::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 10}}
Thread-110819::DEBUG::2012-04-26 10:14:21,636::task::1174::TaskManager.Task::(prepare) Task=`9023ebe8-4202-4119-bb8d-5ad9b1584652`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 10}}
Thread-110819::DEBUG::2012-04-26 10:14:21,637::task::588::TaskManager.Task::(_updateState) Task=`9023ebe8-4202-4119-bb8d-5ad9b1584652`::moving from state preparing -> state finished
Thread-110819::DEBUG::2012-04-26 10:14:21,637::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-110819::DEBUG::2012-04-26 10:14:21,638::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-110819::DEBUG::2012-04-26 10:14:21,639::task::980::TaskManager.Task::(_decref) Task=`9023ebe8-4202-4119-bb8d-5ad9b1584652`::ref 0 aborting False
Thread-110820::DEBUG::2012-04-26 10:14:21,655::clientIF::261::Storage.Dispatcher.Protect::(wrapper) [172.30.0.229]
Thread-110820::DEBUG::2012-04-26 10:14:21,656::task::588::TaskManager.Task::(_updateState) Task=`1601d4ff-ab77-424a-a677-6df3aa703c4d`::moving from state init -> state preparing
Thread-110820::INFO::2012-04-26 10:14:21,657::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='524a7003-edec-4f52-a38e-b15cadfbe3ef', options=None)
Thread-110820::DEBUG::2012-04-26 10:14:21,658::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.524a7003-edec-4f52-a38e-b15cadfbe3ef`ReqID=`239079f4-2f57-4ca6-8a4f-f0944666cfed`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '1878' at 'getStoragePoolInfo'
Thread-110820::DEBUG::2012-04-26 10:14:21,659::resourceManager::483::ResourceManager::(registerResource) Trying to register resource 'Storage.524a7003-edec-4f52-a38e-b15cadfbe3ef' for lock type 'shared'
Thread-110820::DEBUG::2012-04-26 10:14:21,660::resourceManager::525::ResourceManager::(registerResource) Resource 'Storage.524a7003-edec-4f52-a38e-b15cadfbe3ef' is free. Now locking as 'shared' (1 active user)
Thread-110820::DEBUG::2012-04-26 10:14:21,661::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.524a7003-edec-4f52-a38e-b15cadfbe3ef`ReqID=`239079f4-2f57-4ca6-8a4f-f0944666cfed`::Granted request
Thread-110820::DEBUG::2012-04-26 10:14:21,662::task::819::TaskManager.Task::(resourceAcquired) Task=`1601d4ff-ab77-424a-a677-6df3aa703c4d`::_resourcesAcquired: Storage.524a7003-edec-4f52-a38e-b15cadfbe3ef (shared)
Thread-110820::DEBUG::2012-04-26 10:14:21,662::task::980::TaskManager.Task::(_decref) Task=`1601d4ff-ab77-424a-a677-6df3aa703c4d`::ref 1 aborting False
Thread-110820::INFO::2012-04-26 10:14:21,666::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '5e2ac537-6a73-4faf-8379-68f3ff26a75d', 'name': 'BLC', 'version': '0', 'domains': 'fce72110-71ae-46be-8811-2fbeaa001ed2:Active,5e2ac537-6a73-4faf-8379-68f3ff26a75d:Active,6d931187-2c83-4c33-8693-ca2570f7c136:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/524a7003-edec-4f52-a38e-b15cadfbe3ef/fce72110-71ae-46be-8811-2fbeaa001ed2/images/11111111-1111-1111-1111-111111111111', 'type': 'NFS', 'master_ver': 1, 'lver': 10}, 'dominfo': {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'status': 'Active', 'diskfree': '212638531584', 'alerts': [], 'disktotal': '1733743181824'}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'status': 'Active', 'diskfree': '212638531584', 'alerts': [], 'disktotal': '1733743181824'}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'status': 'Active', 'diskfree': '212638531584', 'alerts': [], 'disktotal': '1733743181824'}}}
Thread-110820::DEBUG::2012-04-26 10:14:21,666::task::1174::TaskManager.Task::(prepare) Task=`1601d4ff-ab77-424a-a677-6df3aa703c4d`::finished: {'info': {'spm_id': 1, 'master_uuid': '5e2ac537-6a73-4faf-8379-68f3ff26a75d', 'name': 'BLC', 'version': '0', 'domains': 'fce72110-71ae-46be-8811-2fbeaa001ed2:Active,5e2ac537-6a73-4faf-8379-68f3ff26a75d:Active,6d931187-2c83-4c33-8693-ca2570f7c136:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/524a7003-edec-4f52-a38e-b15cadfbe3ef/fce72110-71ae-46be-8811-2fbeaa001ed2/images/11111111-1111-1111-1111-111111111111', 'type': 'NFS', 'master_ver': 1, 'lver': 10}, 'dominfo': {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'status': 'Active', 'diskfree': '212638531584', 'alerts': [], 'disktotal': '1733743181824'}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'status': 'Active', 'diskfree': '212638531584', 'alerts': [], 'disktotal': '1733743181824'}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'status': 'Active', 'diskfree': '212638531584', 'alerts': [], 'disktotal': '1733743181824'}}}
Thread-110820::DEBUG::2012-04-26 10:14:21,667::task::588::TaskManager.Task::(_updateState) Task=`1601d4ff-ab77-424a-a677-6df3aa703c4d`::moving from state preparing -> state finished
Thread-110820::DEBUG::2012-04-26 10:14:21,667::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.524a7003-edec-4f52-a38e-b15cadfbe3ef': < ResourceRef 'Storage.524a7003-edec-4f52-a38e-b15cadfbe3ef', isValid: 'True' obj: 'None'>}
Thread-110820::DEBUG::2012-04-26 10:14:21,667::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-110820::DEBUG::2012-04-26 10:14:21,667::resourceManager::535::ResourceManager::(releaseResource) Trying to release resource 'Storage.524a7003-edec-4f52-a38e-b15cadfbe3ef'
Thread-110820::DEBUG::2012-04-26 10:14:21,668::resourceManager::550::ResourceManager::(releaseResource) Released resource 'Storage.524a7003-edec-4f52-a38e-b15cadfbe3ef' (0 active users)
Thread-110820::DEBUG::2012-04-26 10:14:21,668::resourceManager::555::ResourceManager::(releaseResource) Resource 'Storage.524a7003-edec-4f52-a38e-b15cadfbe3ef' is free, finding out if anyone is waiting for it.
Thread-110820::DEBUG::2012-04-26 10:14:21,668::resourceManager::562::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.524a7003-edec-4f52-a38e-b15cadfbe3ef', Clearing records.
Thread-110820::DEBUG::2012-04-26 10:14:21,668::task::980::TaskManager.Task::(_decref) Task=`1601d4ff-ab77-424a-a677-6df3aa703c4d`::ref 0 aborting False
Thread-110822::DEBUG::2012-04-26 10:14:23,457::clientIF::76::vds::(wrapper) [172.30.0.232]::call getVmStats with ('f73f17a8-a418-4318-af0e-2cea18ab597a',) {}
Thread-110822::DEBUG::2012-04-26 10:14:23,458::clientIF::81::vds::(wrapper) return getVmStats with {'status': {'message': 'Virtual machine does not exist', 'code': 1}}
Thread-110823::DEBUG::2012-04-26 10:14:23,518::clientIF::76::vds::(wrapper) [172.30.0.232]::call migrationCreate with ({'bridge': 'ovirtmgmt', 'acpiEnable': 'true', 'emulatedMachine': 'pc-0.14', 'afterMigrationStatus': 'Up', 'vmId': 'f73f17a8-a418-4318-af0e-2cea18ab597a', 'transparentHugePages': 'true', 'displaySecurePort': '5902', 'spiceSslCipherSuite': 'DEFAULT', 'cpuType': 'Opteron_G3', 'smp': '1', 'pauseCode': 'NOERR', 'migrationDest': 'libvirt', 'macAddr': '00:1a:4a:1e:00:00', 'boot': 'c', 'custom': {}, 'vmType': 'kvm', '_srcDomXML': "<domain type='kvm' id='20'>\n  <name>test1</name>\n  <uuid>f73f17a8-a418-4318-af0e-2cea18ab597a</uuid>\n  <memory>1048576</memory>\n  <currentMemory>1048576</currentMemory>\n  <vcpu>1</vcpu>\n  <cputune>\n    <shares>1020</shares>\n    <period>100000</period>\n    <quota>-1</quota>\n  </cputune>\n  <sysinfo type='smbios'>\n    <system>\n      <entry name='manufacturer'>Red Hat</entry>\n      <entry name='product'>RHEV Hypervisor</entry>\n      <entry name='version'>16-1</entry>\n      <entry name='serial'>44454C4C-5900-105A-804B-B7C04F563258_00:1D:09:FD:8B:80</entry>\n      <entry name='uuid'>f73f17a8-a418-4318-af0e-2cea18ab597a</entry>\n    </system>\n  </sysinfo>\n  <os>\n    <type arch='x86_64' machine='pc-0.14'>hvm</type>\n    <boot dev='hd'/>\n    <smbios mode='sysinfo'/>\n  </os>\n  <features>\n    <acpi/>\n  </features>\n  <cpu match='exact'>\n    <model>Opteron_G3</model>\n    <topology sockets='1' cores='1' threads='1'/>\n  </cpu>\n  <clock offset='variable' adjustment='0'>\n    <timer name='rtc' tickpolicy='catchup'/>\n  </clock>\n  <on_poweroff>destroy</on_poweroff>\n  <on_reboot>restart</on_reboot>\n  <on_crash>destroy</on_crash>\n  <devices>\n    <emulator>/usr/bin/qemu-kvm</emulator>\n    <disk type='file' device='disk'>\n      <driver name='qemu' type='raw' cache='none' error_policy='stop' io='threads'/>\n      <source file='/rhev/data-center/524a7003-edec-4f52-a38e-b15cadfbe3ef/5e2ac537-6a73-4faf-8379-68f3ff26a75d/images/7338426e-3e31-4ffd-ac37-14c22feea80a/27e84476-26ae-4ac2-8ce7-4fdb3e3225b0'/>\n      <target dev='vda' bus='virtio'/>\n      <serial>7338426e-3e31-4ffd-ac37-14c22feea80a</serial>\n      <alias name='virtio-disk0'/>\n      <address type='pci' domain='0x0000' bus='0x00' slot='0x05' function='0x0'/>\n    </disk>\n    <disk type='file' device='cdrom'>\n      <driver name='qemu' type='raw'/>\n      <target dev='hdc' bus='ide'/>\n      <readonly/>\n      <alias name='ide0-1-0'/>\n      <address type='drive' controller='0' bus='1' unit='0'/>\n    </disk>\n    <controller type='virtio-serial' index='0' ports='16'>\n      <alias name='virtio-serial0'/>\n      <address type='pci' domain='0x0000' bus='0x00' slot='0x04' function='0x0'/>\n    </controller>\n    <controller type='ide' index='0'>\n      <alias name='ide0'/>\n      <address type='pci' domain='0x0000' bus='0x00' slot='0x01' function='0x1'/>\n    </controller>\n    <interface type='bridge'>\n      <mac address='00:1a:4a:1e:00:00'/>\n      <source bridge='ovirtmgmt'/>\n      <target dev='vnet1'/>\n      <model type='virtio'/>\n      <alias name='net0'/>\n      <address type='pci' domain='0x0000' bus='0x00' slot='0x03' function='0x0'/>\n    </interface>\n    <channel type='unix'>\n      <source mode='bind' path='/var/lib/libvirt/qemu/channels/test1.com.redhat.rhevm.vdsm'/>\n      <target type='virtio' name='com.redhat.rhevm.vdsm'/>\n      <alias name='channel0'/>\n      <address type='virtio-serial' controller='0' bus='0' port='1'/>\n    </channel>\n    <channel type='spicevmc'>\n      <target type='virtio' name='com.redhat.spice.0'/>\n      <alias name='channel1'/>\n      <address type='virtio-serial' controller='0' bus='0' port='2'/>\n    </channel>\n    <input type='mouse' bus='ps2'/>\n    <graphics type='spice' port='5901' tlsPort='5902' autoport='yes' listen='0' keymap='en-us' passwdValidTo='2012-04-25T07:18:06' connected='disconnect'>\n      <listen type='address' address='0'/>\n      <channel name='main' mode='secure'/>\n      <channel name='inputs' mode='secure'/>\n    </graphics>\n    <video>\n      <model type='qxl' vram='65536' heads='1'/>\n      <alias name='video0'/>\n      <address type='pci' domain='0x0000' bus='0x00' slot='0x02' function='0x0'/>\n    </video>\n    <memballoon model='none'>\n      <alias name='balloon0'/>\n    </memballoon>\n  </devices>\n  <seclabel type='dynamic' model='selinux' relabel='yes'>\n    <label>system_u:system_r:svirt_t:s0:c39,c972</label>\n    <imagelabel>system_u:object_r:svirt_image_t:s0:c39,c972</imagelabel>\n  </seclabel>\n</domain>\n", 'memSize': 1024, 'smpCoresPerSocket': '1', 'vmName': 'test1', 'spiceMonitors': '1', 'nice': '0', 'status': 'Up', 'clientIp': '', 'displayIp': '0', 'drives': [{'index': '0', 'domainID': '5e2ac537-6a73-4faf-8379-68f3ff26a75d', 'reqsize': '0', 'format': 'raw', 'boot': 'true', 'volumeID': '27e84476-26ae-4ac2-8ce7-4fdb3e3225b0', 'needExtend': False, 'imageID': '7338426e-3e31-4ffd-ac37-14c22feea80a', 'blockDev': False, 'iface': 'virtio', 'propagateErrors': 'off', 'poolID': '524a7003-edec-4f52-a38e-b15cadfbe3ef', 'apparentsize': '21474836480', 'path': '/rhev/data-center/524a7003-edec-4f52-a38e-b15cadfbe3ef/5e2ac537-6a73-4faf-8379-68f3ff26a75d/images/7338426e-3e31-4ffd-ac37-14c22feea80a/27e84476-26ae-4ac2-8ce7-4fdb3e3225b0', 'truesize': '21495832576', 'type': 'disk', 'if': 'virtio'}, {'index': 2, 'iface': 'ide', 'format': 'raw', 'blockDev': False, 'truesize': 0, 'device': 'cdrom', 'path': '', 'propagateErrors': 'off', 'type': 'disk'}], 'keyboardLayout': 'en-us', 'displayPort': '5901', 'spiceSecureChannels': 'smain,sinputs', 'nicModel': 'pv', 'elapsedTimeOffset': 98902.67715907097, 'kvmEnable': 'true', 'pitReinjection': 'false', 'devices': [{'device': 'bridge', 'nicModel': 'virtio', 'macAddr': '00:1a:4a:1e:00:00', 'type': 'interface', 'network': 'ovirtmgmt'}, {'index': '0', 'domainID': '5e2ac537-6a73-4faf-8379-68f3ff26a75d', 'reqsize': '0', 'format': 'raw', 'boot': 'true', 'volumeID': '27e84476-26ae-4ac2-8ce7-4fdb3e3225b0', 'needExtend': False, 'imageID': '7338426e-3e31-4ffd-ac37-14c22feea80a', 'blockDev': False, 'iface': 'virtio', 'propagateErrors': 'off', 'poolID': '524a7003-edec-4f52-a38e-b15cadfbe3ef', 'apparentsize': '21474836480', 'path': '/rhev/data-center/524a7003-edec-4f52-a38e-b15cadfbe3ef/5e2ac537-6a73-4faf-8379-68f3ff26a75d/images/7338426e-3e31-4ffd-ac37-14c22feea80a/27e84476-26ae-4ac2-8ce7-4fdb3e3225b0', 'truesize': '21495832576', 'type': 'disk', 'if': 'virtio'}, {'index': 2, 'iface': 'ide', 'format': 'raw', 'blockDev': False, 'truesize': 0, 'device': 'cdrom', 'path': '', 'propagateErrors': 'off', 'type': 'disk'}, {'device': 'qxl', 'specParams': {'vram': '65536'}, 'type': 'video'}], 'username': 'Unknown', 'timeOffset': '0', 'guestIPs': '', 'display': 'qxl'},) {}
Thread-110823::DEBUG::2012-04-26 10:14:23,520::clientIF::829::vds::(migrationCreate) Migration create
Thread-110823::INFO::2012-04-26 10:14:23,544::clientIF::549::vds::(_getNetworkIp) network None: using 0
Thread-110823::INFO::2012-04-26 10:14:23,545::clientIF::712::vds::(create) vmContainerLock acquired by vm f73f17a8-a418-4318-af0e-2cea18ab597a
Thread-110824::DEBUG::2012-04-26 10:14:23,554::vm::512::vm.Vm::(_startUnderlyingVm) vmId=`f73f17a8-a418-4318-af0e-2cea18ab597a`::Start
Thread-110823::DEBUG::2012-04-26 10:14:23,555::clientIF::725::vds::(create) Total desktops after creation of f73f17a8-a418-4318-af0e-2cea18ab597a is 1
Thread-110824::DEBUG::2012-04-26 10:14:23,556::vm::516::vm.Vm::(_startUnderlyingVm) vmId=`f73f17a8-a418-4318-af0e-2cea18ab597a`::_ongoingCreations acquired
Thread-110823::DEBUG::2012-04-26 10:14:23,556::libvirtvm::1504::vm.Vm::(waitForMigrationDestinationPrepare) vmId=`f73f17a8-a418-4318-af0e-2cea18ab597a`::migration destination: waiting 31s for path preparation
Thread-110824::INFO::2012-04-26 10:14:23,557::libvirtvm::1105::vm.Vm::(_run) vmId=`f73f17a8-a418-4318-af0e-2cea18ab597a`::VM wrapper has started
Thread-110824::DEBUG::2012-04-26 10:14:23,559::task::588::TaskManager.Task::(_updateState) Task=`bd60c4e9-877c-4400-9015-c9a6d6218676`::moving from state init -> state preparing
Thread-110824::INFO::2012-04-26 10:14:23,559::logUtils::37::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='5e2ac537-6a73-4faf-8379-68f3ff26a75d', spUUID='524a7003-edec-4f52-a38e-b15cadfbe3ef', imgUUID='7338426e-3e31-4ffd-ac37-14c22feea80a', volUUID='27e84476-26ae-4ac2-8ce7-4fdb3e3225b0', options=None)
Thread-110824::DEBUG::2012-04-26 10:14:23,561::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.5e2ac537-6a73-4faf-8379-68f3ff26a75d`ReqID=`845d4f67-0bf3-4981-ac88-c7684017cc14`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2352' at 'getVolumeSize'
Thread-110824::DEBUG::2012-04-26 10:14:23,562::resourceManager::483::ResourceManager::(registerResource) Trying to register resource 'Storage.5e2ac537-6a73-4faf-8379-68f3ff26a75d' for lock type 'shared'
Thread-110824::DEBUG::2012-04-26 10:14:23,563::resourceManager::525::ResourceManager::(registerResource) Resource 'Storage.5e2ac537-6a73-4faf-8379-68f3ff26a75d' is free. Now locking as 'shared' (1 active user)
Thread-110824::DEBUG::2012-04-26 10:14:23,563::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.5e2ac537-6a73-4faf-8379-68f3ff26a75d`ReqID=`845d4f67-0bf3-4981-ac88-c7684017cc14`::Granted request
Thread-110824::DEBUG::2012-04-26 10:14:23,564::task::819::TaskManager.Task::(resourceAcquired) Task=`bd60c4e9-877c-4400-9015-c9a6d6218676`::_resourcesAcquired: Storage.5e2ac537-6a73-4faf-8379-68f3ff26a75d (shared)
Thread-110824::DEBUG::2012-04-26 10:14:23,564::task::980::TaskManager.Task::(_decref) Task=`bd60c4e9-877c-4400-9015-c9a6d6218676`::ref 1 aborting False
Thread-110824::DEBUG::2012-04-26 10:14:23,567::fileVolume::537::Storage.Volume::(validateVolumePath) validate path for 27e84476-26ae-4ac2-8ce7-4fdb3e3225b0
Thread-110824::DEBUG::2012-04-26 10:14:23,572::fileVolume::537::Storage.Volume::(validateVolumePath) validate path for 27e84476-26ae-4ac2-8ce7-4fdb3e3225b0
Thread-110824::INFO::2012-04-26 10:14:23,575::logUtils::39::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '21495832576', 'apparentsize': '21474836480'}
Thread-110824::DEBUG::2012-04-26 10:14:23,575::task::1174::TaskManager.Task::(prepare) Task=`bd60c4e9-877c-4400-9015-c9a6d6218676`::finished: {'truesize': '21495832576', 'apparentsize': '21474836480'}
Thread-110824::DEBUG::2012-04-26 10:14:23,576::task::588::TaskManager.Task::(_updateState) Task=`bd60c4e9-877c-4400-9015-c9a6d6218676`::moving from state preparing -> state finished
Thread-110824::DEBUG::2012-04-26 10:14:23,576::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.5e2ac537-6a73-4faf-8379-68f3ff26a75d': < ResourceRef 'Storage.5e2ac537-6a73-4faf-8379-68f3ff26a75d', isValid: 'True' obj: 'None'>}
Thread-110824::DEBUG::2012-04-26 10:14:23,577::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-110824::DEBUG::2012-04-26 10:14:23,578::resourceManager::535::ResourceManager::(releaseResource) Trying to release resource 'Storage.5e2ac537-6a73-4faf-8379-68f3ff26a75d'
Thread-110824::DEBUG::2012-04-26 10:14:23,579::resourceManager::550::ResourceManager::(releaseResource) Released resource 'Storage.5e2ac537-6a73-4faf-8379-68f3ff26a75d' (0 active users)
Thread-110824::DEBUG::2012-04-26 10:14:23,579::resourceManager::555::ResourceManager::(releaseResource) Resource 'Storage.5e2ac537-6a73-4faf-8379-68f3ff26a75d' is free, finding out if anyone is waiting for it.
Thread-110824::DEBUG::2012-04-26 10:14:23,580::resourceManager::562::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.5e2ac537-6a73-4faf-8379-68f3ff26a75d', Clearing records.
Thread-110824::DEBUG::2012-04-26 10:14:23,581::task::980::TaskManager.Task::(_decref) Task=`bd60c4e9-877c-4400-9015-c9a6d6218676`::ref 0 aborting False
Thread-110824::DEBUG::2012-04-26 10:14:23,582::task::588::TaskManager.Task::(_updateState) Task=`860493eb-861b-4ae1-905c-ec0af1d554b6`::moving from state init -> state preparing
Thread-110824::INFO::2012-04-26 10:14:23,583::logUtils::37::dispatcher::(wrapper) Run and protect: getStorageDomainInfo(sdUUID='5e2ac537-6a73-4faf-8379-68f3ff26a75d', options=None)
Thread-110824::INFO::2012-04-26 10:14:23,583::fileSD::195::Storage.StorageDomain::(validate) sdUUID=5e2ac537-6a73-4faf-8379-68f3ff26a75d
Thread-110824::DEBUG::2012-04-26 10:14:23,586::persistentDict::216::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=VMDomain', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=BLC', 'POOL_DOMAINS=fce72110-71ae-46be-8811-2fbeaa001ed2:Active,5e2ac537-6a73-4faf-8379-68f3ff26a75d:Active,6d931187-2c83-4c33-8693-ca2570f7c136:Active', 'POOL_SPM_ID=1', 'POOL_SPM_LVER=10', 'POOL_UUID=524a7003-edec-4f52-a38e-b15cadfbe3ef', 'REMOTE_PATH=192.168.8.28:/export/data/Ovirt-Domain/vmdomain', 'ROLE=Master', 'SDUUID=5e2ac537-6a73-4faf-8379-68f3ff26a75d', 'TYPE=NFS', 'VERSION=0', '_SHA_CKSUM=6cea80b04ba091c9ed94475268c7551289bd6394']
Thread-110824::DEBUG::2012-04-26 10:14:23,588::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.5e2ac537-6a73-4faf-8379-68f3ff26a75d`ReqID=`9e4cab87-ac0b-4d5b-a0e0-4016f0d805d7`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2032' at 'getStorageDomainInfo'
Thread-110824::DEBUG::2012-04-26 10:14:23,589::resourceManager::483::ResourceManager::(registerResource) Trying to register resource 'Storage.5e2ac537-6a73-4faf-8379-68f3ff26a75d' for lock type 'shared'
Thread-110824::DEBUG::2012-04-26 10:14:23,590::resourceManager::525::ResourceManager::(registerResource) Resource 'Storage.5e2ac537-6a73-4faf-8379-68f3ff26a75d' is free. Now locking as 'shared' (1 active user)
Thread-110824::DEBUG::2012-04-26 10:14:23,591::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.5e2ac537-6a73-4faf-8379-68f3ff26a75d`ReqID=`9e4cab87-ac0b-4d5b-a0e0-4016f0d805d7`::Granted request
Thread-110824::DEBUG::2012-04-26 10:14:23,592::task::819::TaskManager.Task::(resourceAcquired) Task=`860493eb-861b-4ae1-905c-ec0af1d554b6`::_resourcesAcquired: Storage.5e2ac537-6a73-4faf-8379-68f3ff26a75d (shared)
Thread-110824::DEBUG::2012-04-26 10:14:23,592::task::980::TaskManager.Task::(_decref) Task=`860493eb-861b-4ae1-905c-ec0af1d554b6`::ref 1 aborting False
Thread-110824::INFO::2012-04-26 10:14:23,605::logUtils::39::dispatcher::(wrapper) Run and protect: getStorageDomainInfo, Return response: {'info': {'uuid': '5e2ac537-6a73-4faf-8379-68f3ff26a75d', 'master_ver': 1, 'lver': 10, 'version': '0', 'role': 'Master', 'remotePath': '192.168.8.28:/export/data/Ovirt-Domain/vmdomain', 'spm_id': 1, 'type': 'NFS', 'class': 'Data', 'pool': ['524a7003-edec-4f52-a38e-b15cadfbe3ef'], 'name': 'VMDomain'}}
Thread-110824::DEBUG::2012-04-26 10:14:23,606::task::1174::TaskManager.Task::(prepare) Task=`860493eb-861b-4ae1-905c-ec0af1d554b6`::finished: {'info': {'uuid': '5e2ac537-6a73-4faf-8379-68f3ff26a75d', 'master_ver': 1, 'lver': 10, 'version': '0', 'role': 'Master', 'remotePath': '192.168.8.28:/export/data/Ovirt-Domain/vmdomain', 'spm_id': 1, 'type': 'NFS', 'class': 'Data', 'pool': ['524a7003-edec-4f52-a38e-b15cadfbe3ef'], 'name': 'VMDomain'}}
Thread-110824::DEBUG::2012-04-26 10:14:23,606::task::588::TaskManager.Task::(_updateState) Task=`860493eb-861b-4ae1-905c-ec0af1d554b6`::moving from state preparing -> state finished
Thread-110824::DEBUG::2012-04-26 10:14:23,606::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.5e2ac537-6a73-4faf-8379-68f3ff26a75d': < ResourceRef 'Storage.5e2ac537-6a73-4faf-8379-68f3ff26a75d', isValid: 'True' obj: 'None'>}
Thread-110824::DEBUG::2012-04-26 10:14:23,606::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-110824::DEBUG::2012-04-26 10:14:23,606::resourceManager::535::ResourceManager::(releaseResource) Trying to release resource 'Storage.5e2ac537-6a73-4faf-8379-68f3ff26a75d'
Thread-110824::DEBUG::2012-04-26 10:14:23,607::resourceManager::550::ResourceManager::(releaseResource) Released resource 'Storage.5e2ac537-6a73-4faf-8379-68f3ff26a75d' (0 active users)
Thread-110824::DEBUG::2012-04-26 10:14:23,607::resourceManager::555::ResourceManager::(releaseResource) Resource 'Storage.5e2ac537-6a73-4faf-8379-68f3ff26a75d' is free, finding out if anyone is waiting for it.
Thread-110824::DEBUG::2012-04-26 10:14:23,607::resourceManager::562::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.5e2ac537-6a73-4faf-8379-68f3ff26a75d', Clearing records.
Thread-110824::DEBUG::2012-04-26 10:14:23,607::task::980::TaskManager.Task::(_decref) Task=`860493eb-861b-4ae1-905c-ec0af1d554b6`::ref 0 aborting False
Thread-110824::DEBUG::2012-04-26 10:14:23,608::task::588::TaskManager.Task::(_updateState) Task=`3ba64588-b7f8-4eb8-a443-26d2b92234c0`::moving from state init -> state preparing
Thread-110824::INFO::2012-04-26 10:14:23,608::logUtils::37::dispatcher::(wrapper) Run and protect: prepareVolume(sdUUID='5e2ac537-6a73-4faf-8379-68f3ff26a75d', spUUID='524a7003-edec-4f52-a38e-b15cadfbe3ef', imgUUID='7338426e-3e31-4ffd-ac37-14c22feea80a', volUUID='27e84476-26ae-4ac2-8ce7-4fdb3e3225b0', rw=True, options=None)
Thread-110824::DEBUG::2012-04-26 10:14:23,608::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.5e2ac537-6a73-4faf-8379-68f3ff26a75d`ReqID=`6515c65f-33e5-4c6f-a677-8e142c0e3fcf`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2423' at 'prepareVolume'
Thread-110824::DEBUG::2012-04-26 10:14:23,609::resourceManager::483::ResourceManager::(registerResource) Trying to register resource 'Storage.5e2ac537-6a73-4faf-8379-68f3ff26a75d' for lock type 'shared'
Thread-110824::DEBUG::2012-04-26 10:14:23,609::resourceManager::525::ResourceManager::(registerResource) Resource 'Storage.5e2ac537-6a73-4faf-8379-68f3ff26a75d' is free. Now locking as 'shared' (1 active user)
Thread-110824::DEBUG::2012-04-26 10:14:23,609::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.5e2ac537-6a73-4faf-8379-68f3ff26a75d`ReqID=`6515c65f-33e5-4c6f-a677-8e142c0e3fcf`::Granted request
Thread-110824::DEBUG::2012-04-26 10:14:23,609::task::819::TaskManager.Task::(resourceAcquired) Task=`3ba64588-b7f8-4eb8-a443-26d2b92234c0`::_resourcesAcquired: Storage.5e2ac537-6a73-4faf-8379-68f3ff26a75d (shared)
Thread-110824::DEBUG::2012-04-26 10:14:23,610::task::980::TaskManager.Task::(_decref) Task=`3ba64588-b7f8-4eb8-a443-26d2b92234c0`::ref 1 aborting False
Thread-110824::DEBUG::2012-04-26 10:14:23,610::resourceManager::175::ResourceManager.Request::(__init__) ResName=`5e2ac537-6a73-4faf-8379-68f3ff26a75d_imageNS.7338426e-3e31-4ffd-ac37-14c22feea80a`ReqID=`82e15858-f4c7-481a-9687-740590752b20`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2428' at 'prepareVolume'
Thread-110824::DEBUG::2012-04-26 10:14:23,610::resourceManager::483::ResourceManager::(registerResource) Trying to register resource '5e2ac537-6a73-4faf-8379-68f3ff26a75d_imageNS.7338426e-3e31-4ffd-ac37-14c22feea80a' for lock type 'exclusive'
Thread-110824::DEBUG::2012-04-26 10:14:23,614::fileVolume::537::Storage.Volume::(validateVolumePath) validate path for 27e84476-26ae-4ac2-8ce7-4fdb3e3225b0
Thread-110824::DEBUG::2012-04-26 10:14:23,619::fileVolume::537::Storage.Volume::(validateVolumePath) validate path for 27e84476-26ae-4ac2-8ce7-4fdb3e3225b0
Thread-110824::DEBUG::2012-04-26 10:14:23,624::fileVolume::537::Storage.Volume::(validateVolumePath) validate path for 27e84476-26ae-4ac2-8ce7-4fdb3e3225b0
Thread-110824::INFO::2012-04-26 10:14:23,629::image::354::Storage.Image::(getChain) sdUUID=5e2ac537-6a73-4faf-8379-68f3ff26a75d imgUUID=7338426e-3e31-4ffd-ac37-14c22feea80a chain=[<storage.fileVolume.FileVolume instance at 0x7f816805ab90>] 
Thread-110824::DEBUG::2012-04-26 10:14:23,632::resourceManager::175::ResourceManager.Request::(__init__) ResName=`5e2ac537-6a73-4faf-8379-68f3ff26a75d_volumeNS.27e84476-26ae-4ac2-8ce7-4fdb3e3225b0`ReqID=`07cfdaca-bfdc-46c4-8233-9ef87c928cd1`::Request was made in '/usr/share/vdsm/storage/resourceFactories.py' line '165' at '__getResourceCandidatesList'
Thread-110824::DEBUG::2012-04-26 10:14:23,633::resourceManager::483::ResourceManager::(registerResource) Trying to register resource '5e2ac537-6a73-4faf-8379-68f3ff26a75d_volumeNS.27e84476-26ae-4ac2-8ce7-4fdb3e3225b0' for lock type 'exclusive'
Thread-110824::DEBUG::2012-04-26 10:14:23,634::resourceManager::525::ResourceManager::(registerResource) Resource '5e2ac537-6a73-4faf-8379-68f3ff26a75d_volumeNS.27e84476-26ae-4ac2-8ce7-4fdb3e3225b0' is free. Now locking as 'exclusive' (1 active user)
Thread-110824::DEBUG::2012-04-26 10:14:23,634::resourceManager::212::ResourceManager.Request::(grant) ResName=`5e2ac537-6a73-4faf-8379-68f3ff26a75d_volumeNS.27e84476-26ae-4ac2-8ce7-4fdb3e3225b0`ReqID=`07cfdaca-bfdc-46c4-8233-9ef87c928cd1`::Granted request
Thread-110824::DEBUG::2012-04-26 10:14:23,636::resourceManager::525::ResourceManager::(registerResource) Resource '5e2ac537-6a73-4faf-8379-68f3ff26a75d_imageNS.7338426e-3e31-4ffd-ac37-14c22feea80a' is free. Now locking as 'exclusive' (1 active user)
Thread-110824::DEBUG::2012-04-26 10:14:23,636::resourceManager::212::ResourceManager.Request::(grant) ResName=`5e2ac537-6a73-4faf-8379-68f3ff26a75d_imageNS.7338426e-3e31-4ffd-ac37-14c22feea80a`ReqID=`82e15858-f4c7-481a-9687-740590752b20`::Granted request
Thread-110824::DEBUG::2012-04-26 10:14:23,639::fileVolume::537::Storage.Volume::(validateVolumePath) validate path for 27e84476-26ae-4ac2-8ce7-4fdb3e3225b0
Thread-110824::INFO::2012-04-26 10:14:23,642::volume::534::Storage.Volume::(prepare) Volume: preparing volume 5e2ac537-6a73-4faf-8379-68f3ff26a75d/27e84476-26ae-4ac2-8ce7-4fdb3e3225b0
Thread-110824::INFO::2012-04-26 10:14:23,654::logUtils::39::dispatcher::(wrapper) Run and protect: prepareVolume, Return response: None
Thread-110824::DEBUG::2012-04-26 10:14:23,655::task::1174::TaskManager.Task::(prepare) Task=`3ba64588-b7f8-4eb8-a443-26d2b92234c0`::finished: None
Thread-110824::DEBUG::2012-04-26 10:14:23,656::task::588::TaskManager.Task::(_updateState) Task=`3ba64588-b7f8-4eb8-a443-26d2b92234c0`::moving from state preparing -> state finished
Thread-110824::DEBUG::2012-04-26 10:14:23,656::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.5e2ac537-6a73-4faf-8379-68f3ff26a75d': < ResourceRef 'Storage.5e2ac537-6a73-4faf-8379-68f3ff26a75d', isValid: 'True' obj: 'None'>}
Thread-110824::DEBUG::2012-04-26 10:14:23,657::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-110824::DEBUG::2012-04-26 10:14:23,658::resourceManager::535::ResourceManager::(releaseResource) Trying to release resource 'Storage.5e2ac537-6a73-4faf-8379-68f3ff26a75d'
Thread-110824::DEBUG::2012-04-26 10:14:23,659::resourceManager::550::ResourceManager::(releaseResource) Released resource 'Storage.5e2ac537-6a73-4faf-8379-68f3ff26a75d' (0 active users)
Thread-110824::DEBUG::2012-04-26 10:14:23,659::resourceManager::555::ResourceManager::(releaseResource) Resource 'Storage.5e2ac537-6a73-4faf-8379-68f3ff26a75d' is free, finding out if anyone is waiting for it.
Thread-110824::DEBUG::2012-04-26 10:14:23,660::resourceManager::562::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.5e2ac537-6a73-4faf-8379-68f3ff26a75d', Clearing records.
Thread-110824::DEBUG::2012-04-26 10:14:23,661::task::980::TaskManager.Task::(_decref) Task=`3ba64588-b7f8-4eb8-a443-26d2b92234c0`::ref 0 aborting False
Thread-110824::DEBUG::2012-04-26 10:14:23,662::task::588::TaskManager.Task::(_updateState) Task=`5907de99-d08d-4802-9d09-f7ab2583efaa`::moving from state init -> state preparing
Thread-110824::INFO::2012-04-26 10:14:23,663::logUtils::37::dispatcher::(wrapper) Run and protect: getVolumePath(sdUUID='5e2ac537-6a73-4faf-8379-68f3ff26a75d', spUUID='524a7003-edec-4f52-a38e-b15cadfbe3ef', imgUUID='7338426e-3e31-4ffd-ac37-14c22feea80a', volUUID='27e84476-26ae-4ac2-8ce7-4fdb3e3225b0', options=None)
Thread-110824::DEBUG::2012-04-26 10:14:23,664::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.5e2ac537-6a73-4faf-8379-68f3ff26a75d`ReqID=`ea414466-6d9a-4c67-9277-7de487f5a085`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2400' at 'getVolumePath'
Thread-110824::DEBUG::2012-04-26 10:14:23,664::resourceManager::483::ResourceManager::(registerResource) Trying to register resource 'Storage.5e2ac537-6a73-4faf-8379-68f3ff26a75d' for lock type 'shared'
Thread-110824::DEBUG::2012-04-26 10:14:23,664::resourceManager::525::ResourceManager::(registerResource) Resource 'Storage.5e2ac537-6a73-4faf-8379-68f3ff26a75d' is free. Now locking as 'shared' (1 active user)
Thread-110824::DEBUG::2012-04-26 10:14:23,664::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.5e2ac537-6a73-4faf-8379-68f3ff26a75d`ReqID=`ea414466-6d9a-4c67-9277-7de487f5a085`::Granted request
Thread-110824::DEBUG::2012-04-26 10:14:23,665::task::819::TaskManager.Task::(resourceAcquired) Task=`5907de99-d08d-4802-9d09-f7ab2583efaa`::_resourcesAcquired: Storage.5e2ac537-6a73-4faf-8379-68f3ff26a75d (shared)
Thread-110824::DEBUG::2012-04-26 10:14:23,665::task::980::TaskManager.Task::(_decref) Task=`5907de99-d08d-4802-9d09-f7ab2583efaa`::ref 1 aborting False
Thread-110824::DEBUG::2012-04-26 10:14:23,667::fileVolume::537::Storage.Volume::(validateVolumePath) validate path for 27e84476-26ae-4ac2-8ce7-4fdb3e3225b0
Thread-110824::INFO::2012-04-26 10:14:23,669::logUtils::39::dispatcher::(wrapper) Run and protect: getVolumePath, Return response: {'path': '/rhev/data-center/524a7003-edec-4f52-a38e-b15cadfbe3ef/5e2ac537-6a73-4faf-8379-68f3ff26a75d/images/7338426e-3e31-4ffd-ac37-14c22feea80a/27e84476-26ae-4ac2-8ce7-4fdb3e3225b0'}
Thread-110824::DEBUG::2012-04-26 10:14:23,670::task::1174::TaskManager.Task::(prepare) Task=`5907de99-d08d-4802-9d09-f7ab2583efaa`::finished: {'path': '/rhev/data-center/524a7003-edec-4f52-a38e-b15cadfbe3ef/5e2ac537-6a73-4faf-8379-68f3ff26a75d/images/7338426e-3e31-4ffd-ac37-14c22feea80a/27e84476-26ae-4ac2-8ce7-4fdb3e3225b0'}
Thread-110824::DEBUG::2012-04-26 10:14:23,671::task::588::TaskManager.Task::(_updateState) Task=`5907de99-d08d-4802-9d09-f7ab2583efaa`::moving from state preparing -> state finished
Thread-110824::DEBUG::2012-04-26 10:14:23,671::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.5e2ac537-6a73-4faf-8379-68f3ff26a75d': < ResourceRef 'Storage.5e2ac537-6a73-4faf-8379-68f3ff26a75d', isValid: 'True' obj: 'None'>}
Thread-110824::DEBUG::2012-04-26 10:14:23,672::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-110824::DEBUG::2012-04-26 10:14:23,673::resourceManager::535::ResourceManager::(releaseResource) Trying to release resource 'Storage.5e2ac537-6a73-4faf-8379-68f3ff26a75d'
Thread-110824::DEBUG::2012-04-26 10:14:23,673::resourceManager::550::ResourceManager::(releaseResource) Released resource 'Storage.5e2ac537-6a73-4faf-8379-68f3ff26a75d' (0 active users)
Thread-110824::DEBUG::2012-04-26 10:14:23,674::resourceManager::555::ResourceManager::(releaseResource) Resource 'Storage.5e2ac537-6a73-4faf-8379-68f3ff26a75d' is free, finding out if anyone is waiting for it.
Thread-110824::DEBUG::2012-04-26 10:14:23,675::resourceManager::562::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.5e2ac537-6a73-4faf-8379-68f3ff26a75d', Clearing records.
Thread-110824::DEBUG::2012-04-26 10:14:23,675::task::980::TaskManager.Task::(_decref) Task=`5907de99-d08d-4802-9d09-f7ab2583efaa`::ref 0 aborting False
Thread-110824::INFO::2012-04-26 10:14:23,676::clientIF::606::vds::(_prepareVolumePath) prepared volume path: /rhev/data-center/524a7003-edec-4f52-a38e-b15cadfbe3ef/5e2ac537-6a73-4faf-8379-68f3ff26a75d/images/7338426e-3e31-4ffd-ac37-14c22feea80a/27e84476-26ae-4ac2-8ce7-4fdb3e3225b0
Thread-110824::INFO::2012-04-26 10:14:23,677::clientIF::606::vds::(_prepareVolumePath) prepared volume path: 
Thread-110824::DEBUG::2012-04-26 10:14:23,678::utils::595::Storage.Misc.excCmd::(execCmd) '/usr/bin/sudo -n /sbin/service ksmtuned retune' (cwd None)
Thread-110823::DEBUG::2012-04-26 10:14:23,679::clientIF::841::vds::(migrationCreate) Destination VM creation succeeded
Thread-110823::DEBUG::2012-04-26 10:14:23,680::clientIF::81::vds::(wrapper) return migrationCreate with {'status': {'message': 'Done', 'code': 0}, 'migrationPort': 0, 'params': {'bridge': 'ovirtmgmt', 'acpiEnable': 'true', 'emulatedMachine': 'pc-0.14', 'afterMigrationStatus': 'Up', 'pid': '0', 'transparentHugePages': 'true', 'displaySecurePort': '-1', 'spiceSslCipherSuite': 'DEFAULT', 'cpuType': 'Opteron_G3', 'custom': {}, 'pauseCode': 'NOERR', 'migrationDest': 'libvirt', 'macAddr': '00:1a:4a:1e:00:00', 'boot': 'c', 'smp': '1', 'vmType': 'kvm', 'memSize': 1024, 'smpCoresPerSocket': '1', 'vmName': 'test1', 'spiceMonitors': '1', 'nice': '0', 'status': 'Migration Destination', 'vmId': 'f73f17a8-a418-4318-af0e-2cea18ab597a', 'displayIp': '0', 'drives': [{'index': '0', 'domainID': '5e2ac537-6a73-4faf-8379-68f3ff26a75d', 'reqsize': '0', 'format': 'raw', 'boot': 'true', 'volumeID': '27e84476-26ae-4ac2-8ce7-4fdb3e3225b0', 'needExtend': False, 'imageID': '7338426e-3e31-4ffd-ac37-14c22feea80a', 'blockDev': False, 'iface': 'virtio', 'propagateErrors': 'off', 'poolID': '524a7003-edec-4f52-a38e-b15cadfbe3ef', 'apparentsize': '21474836480', 'path': '/rhev/data-center/524a7003-edec-4f52-a38e-b15cadfbe3ef/5e2ac537-6a73-4faf-8379-68f3ff26a75d/images/7338426e-3e31-4ffd-ac37-14c22feea80a/27e84476-26ae-4ac2-8ce7-4fdb3e3225b0', 'truesize': '21495832576', 'type': 'disk', 'if': 'virtio'}, {'index': 2, 'iface': 'ide', 'format': 'raw', 'blockDev': False, 'truesize': 0, 'device': 'cdrom', 'path': '', 'propagateErrors': 'off', 'type': 'disk'}], 'displayPort': '-1', 'guestIPs': '', 'spiceSecureChannels': 'smain,sinputs', 'nicModel': 'pv', 'keyboardLayout': 'en-us', 'kvmEnable': 'true', 'pitReinjection': 'false', 'devices': [{'device': 'bridge', 'nicModel': 'virtio', 'macAddr': '00:1a:4a:1e:00:00', 'type': 'interface', 'network': 'ovirtmgmt'}, {'index': '0', 'domainID': '5e2ac537-6a73-4faf-8379-68f3ff26a75d', 'reqsize': '0', 'format': 'raw', 'boot': 'true', 'volumeID': '27e84476-26ae-4ac2-8ce7-4fdb3e3225b0', 'needExtend': False, 'imageID': '7338426e-3e31-4ffd-ac37-14c22feea80a', 'blockDev': False, 'iface': 'virtio', 'propagateErrors': 'off', 'poolID': '524a7003-edec-4f52-a38e-b15cadfbe3ef', 'apparentsize': '21474836480', 'path': '/rhev/data-center/524a7003-edec-4f52-a38e-b15cadfbe3ef/5e2ac537-6a73-4faf-8379-68f3ff26a75d/images/7338426e-3e31-4ffd-ac37-14c22feea80a/27e84476-26ae-4ac2-8ce7-4fdb3e3225b0', 'truesize': '21495832576', 'type': 'disk', 'if': 'virtio'}, {'index': 2, 'iface': 'ide', 'format': 'raw', 'blockDev': False, 'truesize': 0, 'device': 'cdrom', 'path': '', 'propagateErrors': 'off', 'type': 'disk'}, {'device': 'qxl', 'specParams': {'vram': '65536'}, 'type': 'video'}], 'username': 'Unknown', 'timeOffset': '0', 'clientIp': '', 'display': 'qxl'}}
Thread-110824::DEBUG::2012-04-26 10:14:23,742::utils::595::Storage.Misc.excCmd::(execCmd) FAILED: <err> = 'Unknown operation retune\n'; <rc> = 1
Thread-110826::DEBUG::2012-04-26 10:14:23,745::clientIF::76::vds::(wrapper) [172.30.0.232]::call destroy with ('f73f17a8-a418-4318-af0e-2cea18ab597a',) {}
Thread-110824::DEBUG::2012-04-26 10:14:23,746::vm::528::vm.Vm::(_startUnderlyingVm) vmId=`f73f17a8-a418-4318-af0e-2cea18ab597a`::_ongoingCreations released
Thread-110826::INFO::2012-04-26 10:14:23,747::clientIF::476::vds::(destroy) vmContainerLock acquired by vm f73f17a8-a418-4318-af0e-2cea18ab597a
Thread-110824::DEBUG::2012-04-26 10:14:23,747::libvirtvm::1199::vm.Vm::(_waitForIncomingMigrationFinish) vmId=`f73f17a8-a418-4318-af0e-2cea18ab597a`::Waiting 300 seconds for end of migration
Thread-110826::DEBUG::2012-04-26 10:14:23,748::libvirtvm::1400::vm.Vm::(destroy) vmId=`f73f17a8-a418-4318-af0e-2cea18ab597a`::destroy Called
Thread-110826::INFO::2012-04-26 10:14:23,749::libvirtvm::1360::vm.Vm::(releaseVm) vmId=`f73f17a8-a418-4318-af0e-2cea18ab597a`::Release VM resources
Thread-110826::DEBUG::2012-04-26 10:14:23,751::utils::595::Storage.Misc.excCmd::(execCmd) '/usr/bin/sudo -n /sbin/service ksmtuned retune' (cwd None)
Thread-110826::DEBUG::2012-04-26 10:14:23,817::utils::595::Storage.Misc.excCmd::(execCmd) FAILED: <err> = 'Unknown operation retune\n'; <rc> = 1
Thread-110826::DEBUG::2012-04-26 10:14:23,818::vm::858::vm.Vm::(_cleanup) vmId=`f73f17a8-a418-4318-af0e-2cea18ab597a`::Drive  cleanup
Thread-110826::INFO::2012-04-26 10:14:23,819::clientIF::617::vds::(_teardownVolumePath) Avoiding tear down drive {'index': 2, 'iface': 'ide', 'format': 'raw', 'blockDev': False, 'truesize': 0, 'device': 'cdrom', 'path': '', 'propagateErrors': 'off', 'type': 'disk'}
Thread-110826::DEBUG::2012-04-26 10:14:23,820::vm::858::vm.Vm::(_cleanup) vmId=`f73f17a8-a418-4318-af0e-2cea18ab597a`::Drive /rhev/data-center/524a7003-edec-4f52-a38e-b15cadfbe3ef/5e2ac537-6a73-4faf-8379-68f3ff26a75d/images/7338426e-3e31-4ffd-ac37-14c22feea80a/27e84476-26ae-4ac2-8ce7-4fdb3e3225b0 cleanup
Thread-110826::DEBUG::2012-04-26 10:14:23,821::task::588::TaskManager.Task::(_updateState) Task=`d1559e5f-f46c-47c6-8475-d9b17fb05c3e`::moving from state init -> state preparing