Thread-103::DEBUG::2015-10-21 20:15:06,200::task::993::Storage.TaskManager.Task::(_decref) Task=`f429d11f-f975-4a01-a036-495fbdf0a158`::ref 0 aborting False
Thread-103::DEBUG::2015-10-21 20:15:06,200::task::595::Storage.TaskManager.Task::(_updateState) Task=`d83c0c96-8b15-48aa-b193-9275e55994ef`::moving from state init -> state preparing
Thread-103::INFO::2015-10-21 20:15:06,201::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b', spUUID='c3715f80-6435-45b6-94c2-a9a2869cd059', imgUUID='d4a36ce0-46cb-4914-b929-761d165079ec', volUUID='b5a1106f-bf0b-420d-a551-403898f008e3', options=None)
Thread-103::INFO::2015-10-21 20:15:06,202::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '435318784', 'apparentsize': '1073741824'}
Thread-103::DEBUG::2015-10-21 20:15:06,202::task::1191::Storage.TaskManager.Task::(prepare) Task=`d83c0c96-8b15-48aa-b193-9275e55994ef`::finished: {'truesize': '435318784', 'apparentsize': '1073741824'}
Thread-103::DEBUG::2015-10-21 20:15:06,202::task::595::Storage.TaskManager.Task::(_updateState) Task=`d83c0c96-8b15-48aa-b193-9275e55994ef`::moving from state preparing -> state finished
Thread-103::DEBUG::2015-10-21 20:15:06,202::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-103::DEBUG::2015-10-21 20:15:06,202::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-103::DEBUG::2015-10-21 20:15:06,202::task::993::Storage.TaskManager.Task::(_decref) Task=`d83c0c96-8b15-48aa-b193-9275e55994ef`::ref 0 aborting False
Thread-103::DEBUG::2015-10-21 20:15:06,260::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-64::DEBUG::2015-10-21 20:15:06,312::fileSD::262::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/_mnt_data_storage/8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-64::DEBUG::2015-10-21 20:15:06,321::fileSD::262::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n513 bytes (513 B) copied, 0.000207273 s, 2.5 MB/s\n'; <rc> = 0
Thread-99::DEBUG::2015-10-21 20:15:06,508::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-91::DEBUG::2015-10-21 20:15:07,032::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
JsonRpc (StompReactor)::DEBUG::2015-10-21 20:15:07,286::stompReactor::98::Broker.StompAdapter::(handle_frame) Handling message <StompFrame command='SEND'>
JsonRpcServer::DEBUG::2015-10-21 20:15:07,287::__init__::530::jsonrpc.JsonRpcServer::(serve_requests) Waiting for request
Thread-32505::DEBUG::2015-10-21 20:15:07,287::__init__::481::jsonrpc.JsonRpcServer::(_serveRequest) Calling 'VM.create' in bridge with {'vmParams': {'acpiEnable': 'true', 'emulatedMachine': 'rhel6.5.0', 'vmId': 'a3d5dc65-ca9d-4d16-899f-7368b9f2c19d', 'memGuaranteedSize': 512, 'transparentHugePages': 'true', 'spiceSslCipherSuite': 'DEFAULT', 'cpuType': 'Haswell', 'smp': '2', 'custom': {}, 'vmType': 'kvm', 'memSize': 1024, 'smpCoresPerSocket': '1', 'vmName': 'build-arm-mcu', 'nice': '0', 'bootMenuEnable': 'false', 'copyPasteEnable': 'true', 'smartcardEnable': 'false', 'fileTransferEnable': 'true', 'keyboardLayout': 'en-us', 'kvmEnable': 'true', 'pitReinjection': 'false', 'displayNetwork': 'ovirtmgmt', 'devices': [{'device': 'qxl', 'specParams': {'vram': '32768', 'ram': '65536', 'heads': '1'}, 'type': 'video', 'deviceId': '14367428-076b-410a-990e-196fb9904914'}, {'index': '2', 'iface': 'ide', 'specParams': {'path': ''}, 'readonly': 'true', 'deviceId': '60965a40-f384-4a67-9aad-6a74e2364ada', 'path': '', 'device': 'cdrom', 'shared': 'false', 'type': 'disk'}, {'index': 0, 'iface': 'virtio', 'format': 'raw', 'bootOrder': '1', 'volumeID': 'a271d353-35b7-4dd2-b722-e2fc3b117a8d', 'imageID': '370d8ba3-d982-4a86-967f-2602b8df1aa0', 'specParams': {}, 'readonly': 'false', 'domainID': '8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b', 'optional': 'false', 'deviceId': '370d8ba3-d982-4a86-967f-2602b8df1aa0', 'poolID': 'c3715f80-6435-45b6-94c2-a9a2869cd059', 'device': 'disk', 'shared': 'false', 'propagateErrors': 'off', 'type': 'disk'}, {'nicModel': 'pv', 'macAddr': '00:1a:4a:69:c2:16', 'linkActive': 'true', 'network': 'server2', 'filter': 'vdsm-no-mac-spoofing', 'specParams': {'inbound': {}, 'outbound': {}}, 'deviceId': '3d892877-430a-4d64-8619-41e9bd834b02', 'device': 'bridge', 'type': 'interface'}, {'device': 'memballoon', 'specParams': {'model': 'virtio'}, 'type': 'balloon', 'deviceId': '23b3be19-5da3-4b53-a3a9-630bec239aa9'}, {'index': '0', 'specParams': {}, 'deviceId': '5bd979ff-8e2d-4585-a9f4-7f9b39614521', 'device': 'scsi', 'model': 'virtio-scsi', 'type': 'controller'}, {'device': 'virtio-serial', 'specParams': {}, 'type': 'controller', 'deviceId': '47826a86-77f2-471c-bd06-f115dc1e259a'}], 'timeOffset': '0', 'maxVCpus': '16', 'spiceSecureChannels': 'smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard', 'display': 'qxl'}, 'vmID': 'a3d5dc65-ca9d-4d16-899f-7368b9f2c19d'}
Thread-32505::INFO::2015-10-21 20:15:07,288::clientIF::394::vds::(createVm) vmContainerLock acquired by vm a3d5dc65-ca9d-4d16-899f-7368b9f2c19d
Thread-32505::DEBUG::2015-10-21 20:15:07,298::clientIF::407::vds::(createVm) Total desktops after creation of a3d5dc65-ca9d-4d16-899f-7368b9f2c19d is 18
Thread-32506::DEBUG::2015-10-21 20:15:07,298::vm::2277::vm.Vm::(_startUnderlyingVm) vmId=`a3d5dc65-ca9d-4d16-899f-7368b9f2c19d`::Start
Thread-32506::DEBUG::2015-10-21 20:15:07,300::vm::2281::vm.Vm::(_startUnderlyingVm) vmId=`a3d5dc65-ca9d-4d16-899f-7368b9f2c19d`::_ongoingCreations acquired
Thread-32505::DEBUG::2015-10-21 20:15:07,300::__init__::514::jsonrpc.JsonRpcServer::(_serveRequest) Return 'VM.create' in bridge with {'acpiEnable': 'true', 'emulatedMachine': 'rhel6.5.0', 'vmId': 'a3d5dc65-ca9d-4d16-899f-7368b9f2c19d', 'memGuaranteedSize': 512, 'transparentHugePages': 'true', 'displaySecurePort': '-1', 'spiceSslCipherSuite': 'DEFAULT', 'cpuType': 'Haswell', 'smp': '2', 'smartcardEnable': 'false', 'custom': {}, 'vmType': 'kvm', 'memSize': 1024, 'smpCoresPerSocket': '1', 'vmName': 'build-arm-mcu', 'nice': '0', 'status': 'WaitForLaunch', 'bootMenuEnable': 'false', 'pid': '0', 'copyPasteEnable': 'true', 'displayIp': '192.168.10.33', 'displayPort': '-1', 'guestDiskMapping': {}, 'clientIp': '', 'fileTransferEnable': 'true', 'nicModel': 'rtl8139,pv', 'keyboardLayout': 'en-us', 'kvmEnable': 'true', 'pitReinjection': 'false', 'displayNetwork': 'ovirtmgmt', 'devices': [{'device': 'qxl', 'specParams': {'vram': '32768', 'ram': '65536', 'heads': '1'}, 'deviceType': 'video', 'type': 'video', 'deviceId': '14367428-076b-410a-990e-196fb9904914'}, {'index': '2', 'iface': 'ide', 'specParams': {'path': ''}, 'readonly': 'true', 'deviceType': 'disk', 'deviceId': '60965a40-f384-4a67-9aad-6a74e2364ada', 'shared': 'false', 'device': 'cdrom', 'path': '', 'type': 'disk'}, {'index': 0, 'iface': 'virtio', 'type': 'disk', 'format': 'raw', 'bootOrder': '1', 'volumeID': 'a271d353-35b7-4dd2-b722-e2fc3b117a8d', 'imageID': '370d8ba3-d982-4a86-967f-2602b8df1aa0', 'specParams': {}, 'readonly': 'false', 'domainID': '8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b', 'deviceType': 'disk', 'deviceId': '370d8ba3-d982-4a86-967f-2602b8df1aa0', 'poolID': 'c3715f80-6435-45b6-94c2-a9a2869cd059', 'device': 'disk', 'shared': 'false', 'propagateErrors': 'off', 'optional': 'false'}, {'nicModel': 'pv', 'macAddr': '00:1a:4a:69:c2:16', 'linkActive': 'true', 'network': 'server2', 'filter': 'vdsm-no-mac-spoofing', 'specParams': {'inbound': {}, 'outbound': {}}, 'deviceType': 'interface', 'deviceId': '3d892877-430a-4d64-8619-41e9bd834b02', 'device': 'bridge', 'type': 'interface'}, {'device': 'memballoon', 'specParams': {'model': 'virtio'}, 'deviceType': 'balloon', 'type': 'balloon', 'deviceId': '23b3be19-5da3-4b53-a3a9-630bec239aa9'}, {'index': '0', 'specParams': {}, 'deviceType': 'controller', 'deviceId': '5bd979ff-8e2d-4585-a9f4-7f9b39614521', 'device': 'scsi', 'model': 'virtio-scsi', 'type': 'controller'}, {'device': 'virtio-serial', 'specParams': {}, 'deviceType': 'controller', 'type': 'controller', 'deviceId': '47826a86-77f2-471c-bd06-f115dc1e259a'}], 'timeOffset': '0', 'maxVCpus': '16', 'spiceSecureChannels': 'smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard', 'display': 'qxl'}
Thread-32506::INFO::2015-10-21 20:15:07,301::vm::3274::vm.Vm::(_run) vmId=`a3d5dc65-ca9d-4d16-899f-7368b9f2c19d`::VM wrapper has started
Thread-32505::DEBUG::2015-10-21 20:15:07,301::stompReactor::163::yajsonrpc.StompServer::(send) Sending response
Thread-32506::DEBUG::2015-10-21 20:15:07,302::task::595::Storage.TaskManager.Task::(_updateState) Task=`6b794bc9-92e0-463e-aba9-1b84b56964a2`::moving from state init -> state preparing
Thread-32506::INFO::2015-10-21 20:15:07,303::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b', spUUID='c3715f80-6435-45b6-94c2-a9a2869cd059', imgUUID='370d8ba3-d982-4a86-967f-2602b8df1aa0', volUUID='a271d353-35b7-4dd2-b722-e2fc3b117a8d', options=None)
Thread-32506::INFO::2015-10-21 20:15:07,305::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '0', 'apparentsize': '10737418240'}
Thread-32506::DEBUG::2015-10-21 20:15:07,305::task::1191::Storage.TaskManager.Task::(prepare) Task=`6b794bc9-92e0-463e-aba9-1b84b56964a2`::finished: {'truesize': '0', 'apparentsize': '10737418240'}
Thread-32506::DEBUG::2015-10-21 20:15:07,305::task::595::Storage.TaskManager.Task::(_updateState) Task=`6b794bc9-92e0-463e-aba9-1b84b56964a2`::moving from state preparing -> state finished
Thread-32506::DEBUG::2015-10-21 20:15:07,305::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-32506::DEBUG::2015-10-21 20:15:07,305::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-32506::DEBUG::2015-10-21 20:15:07,305::task::993::Storage.TaskManager.Task::(_decref) Task=`6b794bc9-92e0-463e-aba9-1b84b56964a2`::ref 0 aborting False
Thread-32506::INFO::2015-10-21 20:15:07,305::clientIF::335::vds::(prepareVolumePath) prepared volume path: 
Thread-32506::DEBUG::2015-10-21 20:15:07,305::task::595::Storage.TaskManager.Task::(_updateState) Task=`e658e331-31db-4986-b42a-3678414bb203`::moving from state init -> state preparing
Thread-32506::INFO::2015-10-21 20:15:07,305::logUtils::44::dispatcher::(wrapper) Run and protect: prepareImage(sdUUID='8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b', spUUID='c3715f80-6435-45b6-94c2-a9a2869cd059', imgUUID='370d8ba3-d982-4a86-967f-2602b8df1aa0', leafUUID='a271d353-35b7-4dd2-b722-e2fc3b117a8d')
Thread-32506::DEBUG::2015-10-21 20:15:07,306::resourceManager::198::Storage.ResourceManager.Request::(__init__) ResName=`Storage.8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b`ReqID=`3f41ec35-2c66-4ef2-9df1-13826af2837d`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3226' at 'prepareImage'
Thread-32506::DEBUG::2015-10-21 20:15:07,306::resourceManager::542::Storage.ResourceManager::(registerResource) Trying to register resource 'Storage.8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b' for lock type 'shared'
Thread-32506::DEBUG::2015-10-21 20:15:07,306::resourceManager::601::Storage.ResourceManager::(registerResource) Resource 'Storage.8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b' is free. Now locking as 'shared' (1 active user)
Thread-32506::DEBUG::2015-10-21 20:15:07,306::resourceManager::238::Storage.ResourceManager.Request::(grant) ResName=`Storage.8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b`ReqID=`3f41ec35-2c66-4ef2-9df1-13826af2837d`::Granted request
Thread-32506::DEBUG::2015-10-21 20:15:07,306::task::827::Storage.TaskManager.Task::(resourceAcquired) Task=`e658e331-31db-4986-b42a-3678414bb203`::_resourcesAcquired: Storage.8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b (shared)
Thread-32506::DEBUG::2015-10-21 20:15:07,306::task::993::Storage.TaskManager.Task::(_decref) Task=`e658e331-31db-4986-b42a-3678414bb203`::ref 1 aborting False
Thread-32506::DEBUG::2015-10-21 20:15:07,308::fileSD::521::Storage.StorageDomain::(activateVolumes) Fixing permissions on /rhev/data-center/mnt/_mnt_data_storage/8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b/images/370d8ba3-d982-4a86-967f-2602b8df1aa0/a271d353-35b7-4dd2-b722-e2fc3b117a8d
Thread-32506::DEBUG::2015-10-21 20:15:07,309::fileUtils::142::Storage.fileUtils::(createdir) Creating directory: /var/run/vdsm/storage/8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b
Thread-32506::WARNING::2015-10-21 20:15:07,311::fileUtils::149::Storage.fileUtils::(createdir) Dir /var/run/vdsm/storage/8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b already exists
Thread-32506::DEBUG::2015-10-21 20:15:07,311::fileSD::496::Storage.StorageDomain::(createImageLinks) Creating symlink from /rhev/data-center/mnt/_mnt_data_storage/8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b/images/370d8ba3-d982-4a86-967f-2602b8df1aa0 to /var/run/vdsm/storage/8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b/370d8ba3-d982-4a86-967f-2602b8df1aa0
Thread-32506::DEBUG::2015-10-21 20:15:07,312::fileSD::501::Storage.StorageDomain::(createImageLinks) img run dir already exists: /var/run/vdsm/storage/8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b/370d8ba3-d982-4a86-967f-2602b8df1aa0
Thread-32506::DEBUG::2015-10-21 20:15:07,318::fileVolume::529::Storage.Volume::(validateVolumePath) validate path for a271d353-35b7-4dd2-b722-e2fc3b117a8d
Thread-32506::INFO::2015-10-21 20:15:07,320::logUtils::47::dispatcher::(wrapper) Run and protect: prepareImage, Return response: {'info': {'domainID': '8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b', 'volType': 'path', 'leaseOffset': 0, 'path': u'/rhev/data-center/mnt/_mnt_data_storage/8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b/images/370d8ba3-d982-4a86-967f-2602b8df1aa0/a271d353-35b7-4dd2-b722-e2fc3b117a8d', 'volumeID': u'a271d353-35b7-4dd2-b722-e2fc3b117a8d', 'leasePath': u'/rhev/data-center/mnt/_mnt_data_storage/8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b/images/370d8ba3-d982-4a86-967f-2602b8df1aa0/a271d353-35b7-4dd2-b722-e2fc3b117a8d.lease', 'imageID': '370d8ba3-d982-4a86-967f-2602b8df1aa0'}, 'path': u'/rhev/data-center/c3715f80-6435-45b6-94c2-a9a2869cd059/8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b/images/370d8ba3-d982-4a86-967f-2602b8df1aa0/a271d353-35b7-4dd2-b722-e2fc3b117a8d', 'imgVolumesInfo': [{'domainID': '8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b', 'volType': 'path', 'leaseOffset': 0, 'path': u'/rhev/data-center/mnt/_mnt_data_storage/8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b/images/370d8ba3-d982-4a86-967f-2602b8df1aa0/a271d353-35b7-4dd2-b722-e2fc3b117a8d', 'volumeID': u'a271d353-35b7-4dd2-b722-e2fc3b117a8d', 'leasePath': u'/rhev/data-center/mnt/_mnt_data_storage/8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b/images/370d8ba3-d982-4a86-967f-2602b8df1aa0/a271d353-35b7-4dd2-b722-e2fc3b117a8d.lease', 'imageID': '370d8ba3-d982-4a86-967f-2602b8df1aa0'}]}
Thread-32506::DEBUG::2015-10-21 20:15:07,320::task::1191::Storage.TaskManager.Task::(prepare) Task=`e658e331-31db-4986-b42a-3678414bb203`::finished: {'info': {'domainID': '8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b', 'volType': 'path', 'leaseOffset': 0, 'path': u'/rhev/data-center/mnt/_mnt_data_storage/8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b/images/370d8ba3-d982-4a86-967f-2602b8df1aa0/a271d353-35b7-4dd2-b722-e2fc3b117a8d', 'volumeID': u'a271d353-35b7-4dd2-b722-e2fc3b117a8d', 'leasePath': u'/rhev/data-center/mnt/_mnt_data_storage/8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b/images/370d8ba3-d982-4a86-967f-2602b8df1aa0/a271d353-35b7-4dd2-b722-e2fc3b117a8d.lease', 'imageID': '370d8ba3-d982-4a86-967f-2602b8df1aa0'}, 'path': u'/rhev/data-center/c3715f80-6435-45b6-94c2-a9a2869cd059/8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b/images/370d8ba3-d982-4a86-967f-2602b8df1aa0/a271d353-35b7-4dd2-b722-e2fc3b117a8d', 'imgVolumesInfo': [{'domainID': '8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b', 'volType': 'path', 'leaseOffset': 0, 'path': u'/rhev/data-center/mnt/_mnt_data_storage/8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b/images/370d8ba3-d982-4a86-967f-2602b8df1aa0/a271d353-35b7-4dd2-b722-e2fc3b117a8d', 'volumeID': u'a271d353-35b7-4dd2-b722-e2fc3b117a8d', 'leasePath': u'/rhev/data-center/mnt/_mnt_data_storage/8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b/images/370d8ba3-d982-4a86-967f-2602b8df1aa0/a271d353-35b7-4dd2-b722-e2fc3b117a8d.lease', 'imageID': '370d8ba3-d982-4a86-967f-2602b8df1aa0'}]}
Thread-32506::DEBUG::2015-10-21 20:15:07,320::task::595::Storage.TaskManager.Task::(_updateState) Task=`e658e331-31db-4986-b42a-3678414bb203`::moving from state preparing -> state finished
Thread-32506::DEBUG::2015-10-21 20:15:07,320::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b': < ResourceRef 'Storage.8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b', isValid: 'True' obj: 'None'>}
Thread-32506::DEBUG::2015-10-21 20:15:07,320::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-32506::DEBUG::2015-10-21 20:15:07,320::resourceManager::616::Storage.ResourceManager::(releaseResource) Trying to release resource 'Storage.8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b'
Thread-32506::DEBUG::2015-10-21 20:15:07,320::resourceManager::635::Storage.ResourceManager::(releaseResource) Released resource 'Storage.8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b' (0 active users)
Thread-32506::DEBUG::2015-10-21 20:15:07,320::resourceManager::641::Storage.ResourceManager::(releaseResource) Resource 'Storage.8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b' is free, finding out if anyone is waiting for it.
Thread-32506::DEBUG::2015-10-21 20:15:07,320::resourceManager::649::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'Storage.8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b', Clearing records.
Thread-32506::DEBUG::2015-10-21 20:15:07,321::task::993::Storage.TaskManager.Task::(_decref) Task=`e658e331-31db-4986-b42a-3678414bb203`::ref 0 aborting False
Thread-32506::INFO::2015-10-21 20:15:07,321::clientIF::335::vds::(prepareVolumePath) prepared volume path: /rhev/data-center/c3715f80-6435-45b6-94c2-a9a2869cd059/8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b/images/370d8ba3-d982-4a86-967f-2602b8df1aa0/a271d353-35b7-4dd2-b722-e2fc3b117a8d
Thread-32506::DEBUG::2015-10-21 20:15:07,329::vm::1071::vm.Vm::(__init__) vmId=`a3d5dc65-ca9d-4d16-899f-7368b9f2c19d`::Ignoring param (target, 1048576) in BalloonDevice
Thread-32506::DEBUG::2015-10-21 20:15:07,336::vm::3313::vm.Vm::(_run) vmId=`a3d5dc65-ca9d-4d16-899f-7368b9f2c19d`::<?xml version="1.0" encoding="utf-8"?>
<domain type="kvm">
	<name>build-arm-mcu</name>
	<uuid>a3d5dc65-ca9d-4d16-899f-7368b9f2c19d</uuid>
	<memory>1048576</memory>
	<currentMemory>1048576</currentMemory>
	<vcpu current="2">16</vcpu>
	<devices>
		<channel type="unix">
			<target name="com.redhat.rhevm.vdsm" type="virtio"/>
			<source mode="bind" path="/var/lib/libvirt/qemu/channels/a3d5dc65-ca9d-4d16-899f-7368b9f2c19d.com.redhat.rhevm.vdsm"/>
		</channel>
		<channel type="unix">
			<target name="org.qemu.guest_agent.0" type="virtio"/>
			<source mode="bind" path="/var/lib/libvirt/qemu/channels/a3d5dc65-ca9d-4d16-899f-7368b9f2c19d.org.qemu.guest_agent.0"/>
		</channel>
		<input bus="ps2" type="mouse"/>
		<memballoon model="virtio"/>
		<controller index="0" model="virtio-scsi" type="scsi"/>
		<controller index="0" ports="16" type="virtio-serial"/>
		<video>
			<model heads="1" ram="65536" type="qxl" vram="32768"/>
		</video>
		<graphics autoport="yes" keymap="en-us" passwd="*****" passwdValidTo="1970-01-01T00:00:01" port="-1" tlsPort="-1" type="spice">
			<channel mode="secure" name="main"/>
			<channel mode="secure" name="inputs"/>
			<channel mode="secure" name="cursor"/>
			<channel mode="secure" name="playback"/>
			<channel mode="secure" name="record"/>
			<channel mode="secure" name="display"/>
			<channel mode="secure" name="usbredir"/>
			<channel mode="secure" name="smartcard"/>
			<listen network="vdsm-ovirtmgmt" type="network"/>
		</graphics>
		<interface type="bridge">
			<mac address="00:1a:4a:69:c2:16"/>
			<model type="virtio"/>
			<source bridge="server2"/>
			<filterref filter="vdsm-no-mac-spoofing"/>
			<link state="up"/>
			<bandwidth/>
		</interface>
		<disk device="cdrom" snapshot="no" type="file">
			<source file="" startupPolicy="optional"/>
			<target bus="ide" dev="hdc"/>
			<readonly/>
			<serial/>
		</disk>
		<disk device="disk" snapshot="no" type="file">
			<source file="/rhev/data-center/c3715f80-6435-45b6-94c2-a9a2869cd059/8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b/images/370d8ba3-d982-4a86-967f-2602b8df1aa0/a271d353-35b7-4dd2-b722-e2fc3b117a8d"/>
			<target bus="virtio" dev="vda"/>
			<serial>370d8ba3-d982-4a86-967f-2602b8df1aa0</serial>
			<boot order="1"/>
			<driver cache="none" error_policy="stop" io="threads" name="qemu" type="raw"/>
		</disk>
		<channel type="spicevmc">
			<target name="com.redhat.spice.0" type="virtio"/>
		</channel>
	</devices>
	<os>
		<type arch="x86_64" machine="rhel6.5.0">hvm</type>
		<smbios mode="sysinfo"/>
	</os>
	<sysinfo type="smbios">
		<system>
			<entry name="manufacturer">oVirt</entry>
			<entry name="product">oVirt Node</entry>
			<entry name="version">6-7.el6.centos.12.3</entry>
			<entry name="serial">03000200-0400-0500-0006-000700080009</entry>
			<entry name="uuid">a3d5dc65-ca9d-4d16-899f-7368b9f2c19d</entry>
		</system>
	</sysinfo>
	<clock adjustment="0" offset="variable">
		<timer name="rtc" tickpolicy="catchup"/>
		<timer name="pit" tickpolicy="delay"/>
		<timer name="hpet" present="no"/>
	</clock>
	<features>
		<acpi/>
	</features>
	<cpu match="exact">
		<model>Haswell</model>
		<topology cores="1" sockets="16" threads="1"/>
	</cpu>
</domain>

Thread-32506::DEBUG::2015-10-21 20:15:07,977::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 1 edom: 0 level: 2 message: internal error unsupported flags (0x1) in function virLockManagerSanlockNew
Thread-32506::DEBUG::2015-10-21 20:15:07,978::vm::2307::vm.Vm::(_startUnderlyingVm) vmId=`a3d5dc65-ca9d-4d16-899f-7368b9f2c19d`::_ongoingCreations released
Thread-32506::ERROR::2015-10-21 20:15:07,978::vm::2344::vm.Vm::(_startUnderlyingVm) vmId=`a3d5dc65-ca9d-4d16-899f-7368b9f2c19d`::The vm start process failed
Traceback (most recent call last):
  File "/usr/share/vdsm/virt/vm.py", line 2284, in _startUnderlyingVm
    self._run()
  File "/usr/share/vdsm/virt/vm.py", line 3348, in _run
    self._connection.createXML(domxml, flags),
  File "/usr/lib/python2.6/site-packages/vdsm/libvirtconnection.py", line 111, in wrapper
    ret = f(*args, **kwargs)
  File "/usr/lib64/python2.6/site-packages/libvirt.py", line 2709, in createXML
    if ret is None:raise libvirtError('virDomainCreateXML() failed', conn=self)
libvirtError: internal error unsupported flags (0x1) in function virLockManagerSanlockNew
Thread-32506::DEBUG::2015-10-21 20:15:07,981::vm::2799::vm.Vm::(setDownStatus) vmId=`a3d5dc65-ca9d-4d16-899f-7368b9f2c19d`::Changed state to Down: internal error unsupported flags (0x1) in function virLockManagerSanlockNew (code=1)
Thread-101::DEBUG::2015-10-21 20:15:08,003::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-123::DEBUG::2015-10-21 20:15:08,003::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
JsonRpc (StompReactor)::DEBUG::2015-10-21 20:15:08,059::stompReactor::98::Broker.StompAdapter::(handle_frame) Handling message <StompFrame command='SEND'>
JsonRpcServer::DEBUG::2015-10-21 20:15:08,059::__init__::530::jsonrpc.JsonRpcServer::(serve_requests) Waiting for request
Thread-32508::DEBUG::2015-10-21 20:15:08,065::stompReactor::163::yajsonrpc.StompServer::(send) Sending response
JsonRpc (StompReactor)::DEBUG::2015-10-21 20:15:08,066::stompReactor::98::Broker.StompAdapter::(handle_frame) Handling message <StompFrame command='SEND'>
JsonRpcServer::DEBUG::2015-10-21 20:15:08,067::__init__::530::jsonrpc.JsonRpcServer::(serve_requests) Waiting for request
Thread-32509::DEBUG::2015-10-21 20:15:08,068::stompReactor::163::yajsonrpc.StompServer::(send) Sending response
JsonRpc (StompReactor)::DEBUG::2015-10-21 20:15:08,071::stompReactor::98::Broker.StompAdapter::(handle_frame) Handling message <StompFrame command='SEND'>
Thread-32510::DEBUG::2015-10-21 20:15:08,071::__init__::481::jsonrpc.JsonRpcServer::(_serveRequest) Calling 'VM.destroy' in bridge with {'vmID': 'a3d5dc65-ca9d-4d16-899f-7368b9f2c19d'}
JsonRpcServer::DEBUG::2015-10-21 20:15:08,071::__init__::530::jsonrpc.JsonRpcServer::(serve_requests) Waiting for request
Thread-32510::INFO::2015-10-21 20:15:08,072::API::332::vds::(destroy) vmContainerLock acquired by vm a3d5dc65-ca9d-4d16-899f-7368b9f2c19d
Thread-32510::DEBUG::2015-10-21 20:15:08,072::vm::5045::vm.Vm::(destroy) vmId=`a3d5dc65-ca9d-4d16-899f-7368b9f2c19d`::destroy Called
Thread-32510::INFO::2015-10-21 20:15:08,073::vm::4971::vm.Vm::(releaseVm) vmId=`a3d5dc65-ca9d-4d16-899f-7368b9f2c19d`::Release VM resources
Thread-32510::WARNING::2015-10-21 20:15:08,073::vm::1966::vm.Vm::(_set_lastStatus) vmId=`a3d5dc65-ca9d-4d16-899f-7368b9f2c19d`::trying to set state to Powering down when already Down
Thread-32510::DEBUG::2015-10-21 20:15:08,073::task::595::Storage.TaskManager.Task::(_updateState) Task=`5894ec3c-37e4-472b-ba64-20ce6d152bc1`::moving from state init -> state preparing
Thread-32510::INFO::2015-10-21 20:15:08,073::logUtils::44::dispatcher::(wrapper) Run and protect: teardownImage(sdUUID='8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b', spUUID='c3715f80-6435-45b6-94c2-a9a2869cd059', imgUUID='370d8ba3-d982-4a86-967f-2602b8df1aa0', volUUID=None)
Thread-32510::DEBUG::2015-10-21 20:15:08,074::resourceManager::198::Storage.ResourceManager.Request::(__init__) ResName=`Storage.8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b`ReqID=`98495072-5d6c-42c0-a63f-25e68bc5af3a`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3278' at 'teardownImage'
Thread-32510::DEBUG::2015-10-21 20:15:08,074::resourceManager::542::Storage.ResourceManager::(registerResource) Trying to register resource 'Storage.8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b' for lock type 'shared'
Thread-32510::DEBUG::2015-10-21 20:15:08,074::resourceManager::601::Storage.ResourceManager::(registerResource) Resource 'Storage.8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b' is free. Now locking as 'shared' (1 active user)
Thread-32510::DEBUG::2015-10-21 20:15:08,074::resourceManager::238::Storage.ResourceManager.Request::(grant) ResName=`Storage.8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b`ReqID=`98495072-5d6c-42c0-a63f-25e68bc5af3a`::Granted request
Thread-32510::DEBUG::2015-10-21 20:15:08,074::task::827::Storage.TaskManager.Task::(resourceAcquired) Task=`5894ec3c-37e4-472b-ba64-20ce6d152bc1`::_resourcesAcquired: Storage.8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b (shared)
Thread-32510::DEBUG::2015-10-21 20:15:08,074::task::993::Storage.TaskManager.Task::(_decref) Task=`5894ec3c-37e4-472b-ba64-20ce6d152bc1`::ref 1 aborting False
Thread-32510::INFO::2015-10-21 20:15:08,074::logUtils::47::dispatcher::(wrapper) Run and protect: teardownImage, Return response: None
Thread-32510::DEBUG::2015-10-21 20:15:08,074::task::1191::Storage.TaskManager.Task::(prepare) Task=`5894ec3c-37e4-472b-ba64-20ce6d152bc1`::finished: None
Thread-32510::DEBUG::2015-10-21 20:15:08,074::task::595::Storage.TaskManager.Task::(_updateState) Task=`5894ec3c-37e4-472b-ba64-20ce6d152bc1`::moving from state preparing -> state finished
Thread-32510::DEBUG::2015-10-21 20:15:08,075::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b': < ResourceRef 'Storage.8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b', isValid: 'True' obj: 'None'>}
Thread-32510::DEBUG::2015-10-21 20:15:08,075::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-32510::DEBUG::2015-10-21 20:15:08,075::resourceManager::616::Storage.ResourceManager::(releaseResource) Trying to release resource 'Storage.8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b'
Thread-32510::DEBUG::2015-10-21 20:15:08,075::resourceManager::635::Storage.ResourceManager::(releaseResource) Released resource 'Storage.8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b' (0 active users)
Thread-32510::DEBUG::2015-10-21 20:15:08,075::resourceManager::641::Storage.ResourceManager::(releaseResource) Resource 'Storage.8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b' is free, finding out if anyone is waiting for it.
Thread-32510::DEBUG::2015-10-21 20:15:08,075::resourceManager::649::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'Storage.8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b', Clearing records.
Thread-32510::DEBUG::2015-10-21 20:15:08,075::task::993::Storage.TaskManager.Task::(_decref) Task=`5894ec3c-37e4-472b-ba64-20ce6d152bc1`::ref 0 aborting False
Thread-32510::WARNING::2015-10-21 20:15:08,075::utils::129::root::(rmFile) File: /var/lib/libvirt/qemu/channels/a3d5dc65-ca9d-4d16-899f-7368b9f2c19d.com.redhat.rhevm.vdsm already removed
Thread-32510::WARNING::2015-10-21 20:15:08,075::utils::129::root::(rmFile) File: /var/lib/libvirt/qemu/channels/a3d5dc65-ca9d-4d16-899f-7368b9f2c19d.org.qemu.guest_agent.0 already removed
Thread-32510::DEBUG::2015-10-21 20:15:08,076::task::595::Storage.TaskManager.Task::(_updateState) Task=`34513edf-039b-4688-acb9-943abc95c245`::moving from state init -> state preparing
Thread-32510::INFO::2015-10-21 20:15:08,076::logUtils::44::dispatcher::(wrapper) Run and protect: inappropriateDevices(thiefId='a3d5dc65-ca9d-4d16-899f-7368b9f2c19d')
Thread-32510::INFO::2015-10-21 20:15:08,078::logUtils::47::dispatcher::(wrapper) Run and protect: inappropriateDevices, Return response: None
Thread-32510::DEBUG::2015-10-21 20:15:08,078::task::1191::Storage.TaskManager.Task::(prepare) Task=`34513edf-039b-4688-acb9-943abc95c245`::finished: None
Thread-32510::DEBUG::2015-10-21 20:15:08,078::task::595::Storage.TaskManager.Task::(_updateState) Task=`34513edf-039b-4688-acb9-943abc95c245`::moving from state preparing -> state finished
Thread-32510::DEBUG::2015-10-21 20:15:08,078::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-32510::DEBUG::2015-10-21 20:15:08,079::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-32510::DEBUG::2015-10-21 20:15:08,079::task::993::Storage.TaskManager.Task::(_decref) Task=`34513edf-039b-4688-acb9-943abc95c245`::ref 0 aborting False
Thread-32510::DEBUG::2015-10-21 20:15:08,079::vm::5039::vm.Vm::(deleteVm) vmId=`a3d5dc65-ca9d-4d16-899f-7368b9f2c19d`::Total desktops after destroy of a3d5dc65-ca9d-4d16-899f-7368b9f2c19d is 17
Thread-32510::DEBUG::2015-10-21 20:15:08,079::__init__::514::jsonrpc.JsonRpcServer::(_serveRequest) Return 'VM.destroy' in bridge with True
Thread-32510::DEBUG::2015-10-21 20:15:08,079::stompReactor::163::yajsonrpc.StompServer::(send) Sending response
Thread-124::DEBUG::2015-10-21 20:15:08,086::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-89::DEBUG::2015-10-21 20:15:08,164::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-100::DEBUG::2015-10-21 20:15:08,789::task::595::Storage.TaskManager.Task::(_updateState) Task=`0c917751-cede-40df-a4f5-fc972e812f30`::moving from state init -> state preparing
Thread-100::INFO::2015-10-21 20:15:08,790::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b', spUUID='c3715f80-6435-45b6-94c2-a9a2869cd059', imgUUID='99805d07-ded9-44e1-bd91-b1f84a0011ce', volUUID='b2c71fa3-8a59-47af-b770-b731a13a1970', options=None)
Thread-100::INFO::2015-10-21 20:15:08,794::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '2147487744', 'apparentsize': '2147483648'}
Thread-100::DEBUG::2015-10-21 20:15:08,794::task::1191::Storage.TaskManager.Task::(prepare) Task=`0c917751-cede-40df-a4f5-fc972e812f30`::finished: {'truesize': '2147487744', 'apparentsize': '2147483648'}
Thread-100::DEBUG::2015-10-21 20:15:08,794::task::595::Storage.TaskManager.Task::(_updateState) Task=`0c917751-cede-40df-a4f5-fc972e812f30`::moving from state preparing -> state finished
Thread-100::DEBUG::2015-10-21 20:15:08,794::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-100::DEBUG::2015-10-21 20:15:08,794::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-100::DEBUG::2015-10-21 20:15:08,794::task::993::Storage.TaskManager.Task::(_decref) Task=`0c917751-cede-40df-a4f5-fc972e812f30`::ref 0 aborting False
Thread-100::DEBUG::2015-10-21 20:15:08,794::task::595::Storage.TaskManager.Task::(_updateState) Task=`c56df1f3-b36e-453c-886c-7c0ebba4bf3c`::moving from state init -> state preparing
Thread-100::INFO::2015-10-21 20:15:08,794::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b', spUUID='c3715f80-6435-45b6-94c2-a9a2869cd059', imgUUID='085f466d-92b7-4997-a7ff-8af9cdef2ed2', volUUID='26197f71-76d0-4883-92fe-a28f585d1dad', options=None)
Thread-100::INFO::2015-10-21 20:15:08,795::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '21474840576', 'apparentsize': '21474836480'}
Thread-100::DEBUG::2015-10-21 20:15:08,795::task::1191::Storage.TaskManager.Task::(prepare) Task=`c56df1f3-b36e-453c-886c-7c0ebba4bf3c`::finished: {'truesize': '21474840576', 'apparentsize': '21474836480'}
Thread-100::DEBUG::2015-10-21 20:15:08,795::task::595::Storage.TaskManager.Task::(_updateState) Task=`c56df1f3-b36e-453c-886c-7c0ebba4bf3c`::moving from state preparing -> state finished
Thread-100::DEBUG::2015-10-21 20:15:08,795::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-100::DEBUG::2015-10-21 20:15:08,796::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-100::DEBUG::2015-10-21 20:15:08,796::task::993::Storage.TaskManager.Task::(_decref) Task=`c56df1f3-b36e-453c-886c-7c0ebba4bf3c`::ref 0 aborting False
Thread-100::DEBUG::2015-10-21 20:15:08,796::task::595::Storage.TaskManager.Task::(_updateState) Task=`2aa235fd-6547-4f95-a74c-b33385f7140b`::moving from state init -> state preparing
Thread-100::INFO::2015-10-21 20:15:08,796::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b', spUUID='c3715f80-6435-45b6-94c2-a9a2869cd059', imgUUID='166c60c2-32aa-4bef-8dc3-3c04a6b20cae', volUUID='9c1da515-c056-486d-b0f4-98197f1fc73a', options=None)
Thread-100::INFO::2015-10-21 20:15:08,797::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '277929984', 'apparentsize': '1073741824'}
Thread-100::DEBUG::2015-10-21 20:15:08,797::task::1191::Storage.TaskManager.Task::(prepare) Task=`2aa235fd-6547-4f95-a74c-b33385f7140b`::finished: {'truesize': '277929984', 'apparentsize': '1073741824'}
Thread-100::DEBUG::2015-10-21 20:15:08,797::task::595::Storage.TaskManager.Task::(_updateState) Task=`2aa235fd-6547-4f95-a74c-b33385f7140b`::moving from state preparing -> state finished
Thread-100::DEBUG::2015-10-21 20:15:08,797::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-100::DEBUG::2015-10-21 20:15:08,797::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-100::DEBUG::2015-10-21 20:15:08,797::task::993::Storage.TaskManager.Task::(_decref) Task=`2aa235fd-6547-4f95-a74c-b33385f7140b`::ref 0 aborting False
Thread-100::DEBUG::2015-10-21 20:15:08,797::task::595::Storage.TaskManager.Task::(_updateState) Task=`61cb7e77-99f7-46ee-b06a-95494e7e6fb3`::moving from state init -> state preparing
Thread-100::INFO::2015-10-21 20:15:08,797::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b', spUUID='c3715f80-6435-45b6-94c2-a9a2869cd059', imgUUID='a81ea779-cbe8-403c-853a-ac92cffb0b7f', volUUID='e59ae5b6-4e70-4f3b-8b59-c237e0fae1ef', options=None)
Thread-100::INFO::2015-10-21 20:15:08,798::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '294592512', 'apparentsize': '1073741824'}
Thread-100::DEBUG::2015-10-21 20:15:08,799::task::1191::Storage.TaskManager.Task::(prepare) Task=`61cb7e77-99f7-46ee-b06a-95494e7e6fb3`::finished: {'truesize': '294592512', 'apparentsize': '1073741824'}
Thread-100::DEBUG::2015-10-21 20:15:08,799::task::595::Storage.TaskManager.Task::(_updateState) Task=`61cb7e77-99f7-46ee-b06a-95494e7e6fb3`::moving from state preparing -> state finished
Thread-100::DEBUG::2015-10-21 20:15:08,799::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-100::DEBUG::2015-10-21 20:15:08,799::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-100::DEBUG::2015-10-21 20:15:08,799::task::993::Storage.TaskManager.Task::(_decref) Task=`61cb7e77-99f7-46ee-b06a-95494e7e6fb3`::ref 0 aborting False
Thread-100::DEBUG::2015-10-21 20:15:08,891::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-96::DEBUG::2015-10-21 20:15:08,957::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-65::DEBUG::2015-10-21 20:15:09,531::fileSD::262::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/_mnt_data__ssd_storage/e1826a4b-eeb8-4ec3-bb6b-ab845d3feb85/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-65::DEBUG::2015-10-21 20:15:09,541::fileSD::262::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n333 bytes (333 B) copied, 0.000194706 s, 1.7 MB/s\n'; <rc> = 0
Thread-66::DEBUG::2015-10-21 20:15:09,585::fileSD::262::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/_mnt_data__bulk_storage/b6901ec1-7992-4ff8-a728-08bc47103f67/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-66::DEBUG::2015-10-21 20:15:09,594::fileSD::262::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n335 bytes (335 B) copied, 0.000187435 s, 1.8 MB/s\n'; <rc> = 0
Thread-126::DEBUG::2015-10-21 20:15:09,646::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-128::DEBUG::2015-10-21 20:15:10,569::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-127::DEBUG::2015-10-21 20:15:10,617::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-125::DEBUG::2015-10-21 20:15:10,700::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-98::DEBUG::2015-10-21 20:15:10,701::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-102::DEBUG::2015-10-21 20:15:10,738::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
JsonRpc (StompReactor)::DEBUG::2015-10-21 20:15:11,121::stompReactor::98::Broker.StompAdapter::(handle_frame) Handling message <StompFrame command='SEND'>
JsonRpcServer::DEBUG::2015-10-21 20:15:11,122::__init__::530::jsonrpc.JsonRpcServer::(serve_requests) Waiting for request
Thread-32511::DEBUG::2015-10-21 20:15:11,128::stompReactor::163::yajsonrpc.StompServer::(send) Sending response
Thread-97::DEBUG::2015-10-21 20:15:12,307::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-92::DEBUG::2015-10-21 20:15:12,308::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-63::DEBUG::2015-10-21 20:15:12,862::fileSD::262::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/esther.joris2k.nl:_mnt_data_iso/2cee08e0-e675-480a-903c-61f5fe244841/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-63::DEBUG::2015-10-21 20:15:12,870::fileSD::262::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n354 bytes (354 B) copied, 0.000101643 s, 3.5 MB/s\n'; <rc> = 0
JsonRpc (StompReactor)::DEBUG::2015-10-21 20:15:14,133::stompReactor::98::Broker.StompAdapter::(handle_frame) Handling message <StompFrame command='SEND'>
JsonRpcServer::DEBUG::2015-10-21 20:15:14,134::__init__::530::jsonrpc.JsonRpcServer::(serve_requests) Waiting for request
Thread-32512::DEBUG::2015-10-21 20:15:14,141::stompReactor::163::yajsonrpc.StompServer::(send) Sending response
JsonRpc (StompReactor)::DEBUG::2015-10-21 20:15:15,679::stompReactor::98::Broker.StompAdapter::(handle_frame) Handling message <StompFrame command='SEND'>
JsonRpcServer::DEBUG::2015-10-21 20:15:15,680::__init__::530::jsonrpc.JsonRpcServer::(serve_requests) Waiting for request
Thread-32513::DEBUG::2015-10-21 20:15:15,680::__init__::481::jsonrpc.JsonRpcServer::(_serveRequest) Calling 'StoragePool.getSpmStatus' in bridge with {'storagepoolID': 'c3715f80-6435-45b6-94c2-a9a2869cd059'}
Thread-32513::DEBUG::2015-10-21 20:15:15,681::task::595::Storage.TaskManager.Task::(_updateState) Task=`8e518e2a-e5a5-4bf9-a425-c6b5dc2d20d8`::moving from state init -> state preparing
Thread-32513::INFO::2015-10-21 20:15:15,681::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='c3715f80-6435-45b6-94c2-a9a2869cd059', options=None)
Thread-32513::INFO::2015-10-21 20:15:15,681::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': -1}}
Thread-32513::DEBUG::2015-10-21 20:15:15,681::task::1191::Storage.TaskManager.Task::(prepare) Task=`8e518e2a-e5a5-4bf9-a425-c6b5dc2d20d8`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': -1}}
Thread-32513::DEBUG::2015-10-21 20:15:15,681::task::595::Storage.TaskManager.Task::(_updateState) Task=`8e518e2a-e5a5-4bf9-a425-c6b5dc2d20d8`::moving from state preparing -> state finished
Thread-32513::DEBUG::2015-10-21 20:15:15,681::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-32513::DEBUG::2015-10-21 20:15:15,682::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-32513::DEBUG::2015-10-21 20:15:15,682::task::993::Storage.TaskManager.Task::(_decref) Task=`8e518e2a-e5a5-4bf9-a425-c6b5dc2d20d8`::ref 0 aborting False
Thread-32513::DEBUG::2015-10-21 20:15:15,682::__init__::514::jsonrpc.JsonRpcServer::(_serveRequest) Return 'StoragePool.getSpmStatus' in bridge with {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': -1}
Thread-32513::DEBUG::2015-10-21 20:15:15,682::stompReactor::163::yajsonrpc.StompServer::(send) Sending response
JsonRpc (StompReactor)::DEBUG::2015-10-21 20:15:15,746::stompReactor::98::Broker.StompAdapter::(handle_frame) Handling message <StompFrame command='SEND'>
Thread-32514::DEBUG::2015-10-21 20:15:15,747::__init__::481::jsonrpc.JsonRpcServer::(_serveRequest) Calling 'StoragePool.getInfo' in bridge with {'storagepoolID': 'c3715f80-6435-45b6-94c2-a9a2869cd059'}
JsonRpcServer::DEBUG::2015-10-21 20:15:15,747::__init__::530::jsonrpc.JsonRpcServer::(serve_requests) Waiting for request
Thread-32514::DEBUG::2015-10-21 20:15:15,748::task::595::Storage.TaskManager.Task::(_updateState) Task=`d6ca8ee8-ba92-4ff0-b422-74f13a2eb687`::moving from state init -> state preparing
Thread-32514::INFO::2015-10-21 20:15:15,748::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='c3715f80-6435-45b6-94c2-a9a2869cd059', options=None)
Thread-32514::DEBUG::2015-10-21 20:15:15,748::resourceManager::198::Storage.ResourceManager.Request::(__init__) ResName=`Storage.c3715f80-6435-45b6-94c2-a9a2869cd059`ReqID=`4bda5bac-dba0-45e4-94b0-c8bb9344a6d0`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2632' at 'getStoragePoolInfo'
Thread-32514::DEBUG::2015-10-21 20:15:15,749::resourceManager::542::Storage.ResourceManager::(registerResource) Trying to register resource 'Storage.c3715f80-6435-45b6-94c2-a9a2869cd059' for lock type 'shared'
Thread-32514::DEBUG::2015-10-21 20:15:15,749::resourceManager::601::Storage.ResourceManager::(registerResource) Resource 'Storage.c3715f80-6435-45b6-94c2-a9a2869cd059' is free. Now locking as 'shared' (1 active user)
Thread-32514::DEBUG::2015-10-21 20:15:15,749::resourceManager::238::Storage.ResourceManager.Request::(grant) ResName=`Storage.c3715f80-6435-45b6-94c2-a9a2869cd059`ReqID=`4bda5bac-dba0-45e4-94b0-c8bb9344a6d0`::Granted request
Thread-32514::DEBUG::2015-10-21 20:15:15,749::task::827::Storage.TaskManager.Task::(resourceAcquired) Task=`d6ca8ee8-ba92-4ff0-b422-74f13a2eb687`::_resourcesAcquired: Storage.c3715f80-6435-45b6-94c2-a9a2869cd059 (shared)
Thread-32514::DEBUG::2015-10-21 20:15:15,749::task::993::Storage.TaskManager.Task::(_decref) Task=`d6ca8ee8-ba92-4ff0-b422-74f13a2eb687`::ref 1 aborting False
Thread-32514::INFO::2015-10-21 20:15:15,749::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'No Description', 'isoprefix': u'/rhev/data-center/mnt/esther.joris2k.nl:_mnt_data_iso/2cee08e0-e675-480a-903c-61f5fe244841/images/11111111-1111-1111-1111-111111111111', 'pool_status': 'connected', 'lver': -1, 'domains': '2cee08e0-e675-480a-903c-61f5fe244841:Active,8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b:Active,b6901ec1-7992-4ff8-a728-08bc47103f67:Active,e1826a4b-eeb8-4ec3-bb6b-ab845d3feb85:Active', 'master_uuid': u'8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b', 'version': '3', 'spm_id': 1, 'type': 'LOCALFS', 'master_ver': 1}, 'dominfo': {'2cee08e0-e675-480a-903c-61f5fe244841': {'status': 'Active', 'diskfree': '266550116352', 'isoprefix': u'/rhev/data-center/mnt/esther.joris2k.nl:_mnt_data_iso/2cee08e0-e675-480a-903c-61f5fe244841/images/11111111-1111-1111-1111-111111111111', 'alerts': [], 'disktotal': '938684186624', 'version': 0}, '8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b': {'status': 'Active', 'diskfree': '266549284864', 'isoprefix': '', 'alerts': [], 'disktotal': '938683396096', 'version': 3}, 'b6901ec1-7992-4ff8-a728-08bc47103f67': {'status': 'Active', 'diskfree': '379594899456', 'isoprefix': '', 'alerts': [], 'disktotal': '1476210552832', 'version': 3}, 'e1826a4b-eeb8-4ec3-bb6b-ab845d3feb85': {'status': 'Active', 'diskfree': '136929796096', 'isoprefix': '', 'alerts': [], 'disktotal': '147831037952', 'version': 3}}}
Thread-32514::DEBUG::2015-10-21 20:15:15,750::task::1191::Storage.TaskManager.Task::(prepare) Task=`d6ca8ee8-ba92-4ff0-b422-74f13a2eb687`::finished: {'info': {'name': 'No Description', 'isoprefix': u'/rhev/data-center/mnt/esther.joris2k.nl:_mnt_data_iso/2cee08e0-e675-480a-903c-61f5fe244841/images/11111111-1111-1111-1111-111111111111', 'pool_status': 'connected', 'lver': -1, 'domains': '2cee08e0-e675-480a-903c-61f5fe244841:Active,8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b:Active,b6901ec1-7992-4ff8-a728-08bc47103f67:Active,e1826a4b-eeb8-4ec3-bb6b-ab845d3feb85:Active', 'master_uuid': u'8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b', 'version': '3', 'spm_id': 1, 'type': 'LOCALFS', 'master_ver': 1}, 'dominfo': {'2cee08e0-e675-480a-903c-61f5fe244841': {'status': 'Active', 'diskfree': '266550116352', 'isoprefix': u'/rhev/data-center/mnt/esther.joris2k.nl:_mnt_data_iso/2cee08e0-e675-480a-903c-61f5fe244841/images/11111111-1111-1111-1111-111111111111', 'alerts': [], 'disktotal': '938684186624', 'version': 0}, '8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b': {'status': 'Active', 'diskfree': '266549284864', 'isoprefix': '', 'alerts': [], 'disktotal': '938683396096', 'version': 3}, 'b6901ec1-7992-4ff8-a728-08bc47103f67': {'status': 'Active', 'diskfree': '379594899456', 'isoprefix': '', 'alerts': [], 'disktotal': '1476210552832', 'version': 3}, 'e1826a4b-eeb8-4ec3-bb6b-ab845d3feb85': {'status': 'Active', 'diskfree': '136929796096', 'isoprefix': '', 'alerts': [], 'disktotal': '147831037952', 'version': 3}}}
Thread-32514::DEBUG::2015-10-21 20:15:15,750::task::595::Storage.TaskManager.Task::(_updateState) Task=`d6ca8ee8-ba92-4ff0-b422-74f13a2eb687`::moving from state preparing -> state finished
Thread-32514::DEBUG::2015-10-21 20:15:15,750::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.c3715f80-6435-45b6-94c2-a9a2869cd059': < ResourceRef 'Storage.c3715f80-6435-45b6-94c2-a9a2869cd059', isValid: 'True' obj: 'None'>}
Thread-32514::DEBUG::2015-10-21 20:15:15,750::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-32514::DEBUG::2015-10-21 20:15:15,750::resourceManager::616::Storage.ResourceManager::(releaseResource) Trying to release resource 'Storage.c3715f80-6435-45b6-94c2-a9a2869cd059'
Thread-32514::DEBUG::2015-10-21 20:15:15,750::resourceManager::635::Storage.ResourceManager::(releaseResource) Released resource 'Storage.c3715f80-6435-45b6-94c2-a9a2869cd059' (0 active users)
Thread-32514::DEBUG::2015-10-21 20:15:15,750::resourceManager::641::Storage.ResourceManager::(releaseResource) Resource 'Storage.c3715f80-6435-45b6-94c2-a9a2869cd059' is free, finding out if anyone is waiting for it.
Thread-32514::DEBUG::2015-10-21 20:15:15,750::resourceManager::649::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'Storage.c3715f80-6435-45b6-94c2-a9a2869cd059', Clearing records.
Thread-32514::DEBUG::2015-10-21 20:15:15,750::task::993::Storage.TaskManager.Task::(_decref) Task=`d6ca8ee8-ba92-4ff0-b422-74f13a2eb687`::ref 0 aborting False
Thread-32514::DEBUG::2015-10-21 20:15:15,750::__init__::514::jsonrpc.JsonRpcServer::(_serveRequest) Return 'StoragePool.getInfo' in bridge with {'info': {'name': 'No Description', 'isoprefix': u'/rhev/data-center/mnt/esther.joris2k.nl:_mnt_data_iso/2cee08e0-e675-480a-903c-61f5fe244841/images/11111111-1111-1111-1111-111111111111', 'pool_status': 'connected', 'lver': -1, 'domains': '2cee08e0-e675-480a-903c-61f5fe244841:Active,8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b:Active,b6901ec1-7992-4ff8-a728-08bc47103f67:Active,e1826a4b-eeb8-4ec3-bb6b-ab845d3feb85:Active', 'master_uuid': u'8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b', 'version': '3', 'spm_id': 1, 'type': 'LOCALFS', 'master_ver': 1}, 'dominfo': {'2cee08e0-e675-480a-903c-61f5fe244841': {'status': 'Active', 'diskfree': '266550116352', 'isoprefix': u'/rhev/data-center/mnt/esther.joris2k.nl:_mnt_data_iso/2cee08e0-e675-480a-903c-61f5fe244841/images/11111111-1111-1111-1111-111111111111', 'alerts': [], 'disktotal': '938684186624', 'version': 0}, '8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b': {'status': 'Active', 'diskfree': '266549284864', 'isoprefix': '', 'alerts': [], 'disktotal': '938683396096', 'version': 3}, 'b6901ec1-7992-4ff8-a728-08bc47103f67': {'status': 'Active', 'diskfree': '379594899456', 'isoprefix': '', 'alerts': [], 'disktotal': '1476210552832', 'version': 3}, 'e1826a4b-eeb8-4ec3-bb6b-ab845d3feb85': {'status': 'Active', 'diskfree': '136929796096', 'isoprefix': '', 'alerts': [], 'disktotal': '147831037952', 'version': 3}}}
Thread-32514::DEBUG::2015-10-21 20:15:15,750::stompReactor::163::yajsonrpc.StompServer::(send) Sending response
Thread-64::DEBUG::2015-10-21 20:15:16,326::fileSD::262::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/_mnt_data_storage/8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-64::DEBUG::2015-10-21 20:15:16,335::fileSD::262::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n513 bytes (513 B) copied, 0.000191537 s, 2.7 MB/s\n'; <rc> = 0
JsonRpc (StompReactor)::DEBUG::2015-10-21 20:15:17,146::stompReactor::98::Broker.StompAdapter::(handle_frame) Handling message <StompFrame command='SEND'>
JsonRpcServer::DEBUG::2015-10-21 20:15:17,147::__init__::530::jsonrpc.JsonRpcServer::(serve_requests) Waiting for request
Thread-32515::DEBUG::2015-10-21 20:15:17,148::task::595::Storage.TaskManager.Task::(_updateState) Task=`6f466636-57a8-4bbe-98db-a9f736386a7c`::moving from state init -> state preparing
Thread-32515::INFO::2015-10-21 20:15:17,149::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-32515::INFO::2015-10-21 20:15:17,149::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'2cee08e0-e675-480a-903c-61f5fe244841': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000101643', 'lastCheck': '4.3', 'valid': True}, '8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b': {'code': 0, 'actual': True, 'version': 3, 'acquired': True, 'delay': '0.000191537', 'lastCheck': '0.8', 'valid': True}, 'b6901ec1-7992-4ff8-a728-08bc47103f67': {'code': 0, 'actual': True, 'version': 3, 'acquired': True, 'delay': '0.000187435', 'lastCheck': '7.6', 'valid': True}, 'e1826a4b-eeb8-4ec3-bb6b-ab845d3feb85': {'code': 0, 'actual': True, 'version': 3, 'acquired': True, 'delay': '0.000194706', 'lastCheck': '7.6', 'valid': True}}
Thread-32515::DEBUG::2015-10-21 20:15:17,149::task::1191::Storage.TaskManager.Task::(prepare) Task=`6f466636-57a8-4bbe-98db-a9f736386a7c`::finished: {'2cee08e0-e675-480a-903c-61f5fe244841': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000101643', 'lastCheck': '4.3', 'valid': True}, '8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b': {'code': 0, 'actual': True, 'version': 3, 'acquired': True, 'delay': '0.000191537', 'lastCheck': '0.8', 'valid': True}, 'b6901ec1-7992-4ff8-a728-08bc47103f67': {'code': 0, 'actual': True, 'version': 3, 'acquired': True, 'delay': '0.000187435', 'lastCheck': '7.6', 'valid': True}, 'e1826a4b-eeb8-4ec3-bb6b-ab845d3feb85': {'code': 0, 'actual': True, 'version': 3, 'acquired': True, 'delay': '0.000194706', 'lastCheck': '7.6', 'valid': True}}
Thread-32515::DEBUG::2015-10-21 20:15:17,149::task::595::Storage.TaskManager.Task::(_updateState) Task=`6f466636-57a8-4bbe-98db-a9f736386a7c`::moving from state preparing -> state finished
Thread-32515::DEBUG::2015-10-21 20:15:17,149::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-32515::DEBUG::2015-10-21 20:15:17,149::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-32515::DEBUG::2015-10-21 20:15:17,149::task::993::Storage.TaskManager.Task::(_decref) Task=`6f466636-57a8-4bbe-98db-a9f736386a7c`::ref 0 aborting False
Thread-32515::DEBUG::2015-10-21 20:15:17,152::stompReactor::163::yajsonrpc.StompServer::(send) Sending response
JsonRpc (StompReactor)::DEBUG::2015-10-21 20:15:17,159::stompReactor::98::Broker.StompAdapter::(handle_frame) Handling message <StompFrame command='SEND'>
JsonRpcServer::DEBUG::2015-10-21 20:15:17,159::__init__::530::jsonrpc.JsonRpcServer::(serve_requests) Waiting for request
Thread-32516::DEBUG::2015-10-21 20:15:17,174::stompReactor::163::yajsonrpc.StompServer::(send) Sending response
Thread-65::DEBUG::2015-10-21 20:15:19,544::fileSD::262::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/_mnt_data__ssd_storage/e1826a4b-eeb8-4ec3-bb6b-ab845d3feb85/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-65::DEBUG::2015-10-21 20:15:19,552::fileSD::262::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n333 bytes (333 B) copied, 0.000192212 s, 1.7 MB/s\n'; <rc> = 0
Thread-66::DEBUG::2015-10-21 20:15:19,596::fileSD::262::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/_mnt_data__bulk_storage/b6901ec1-7992-4ff8-a728-08bc47103f67/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-66::DEBUG::2015-10-21 20:15:19,605::fileSD::262::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n335 bytes (335 B) copied, 0.000265078 s, 1.3 MB/s\n'; <rc> = 0
JsonRpc (StompReactor)::DEBUG::2015-10-21 20:15:20,467::stompReactor::98::Broker.StompAdapter::(handle_frame) Handling message <StompFrame command='SEND'>
JsonRpcServer::DEBUG::2015-10-21 20:15:20,468::__init__::530::jsonrpc.JsonRpcServer::(serve_requests) Waiting for request
Thread-32517::DEBUG::2015-10-21 20:15:20,475::stompReactor::163::yajsonrpc.StompServer::(send) Sending response
Thread-103::DEBUG::2015-10-21 20:15:21,274::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-99::DEBUG::2015-10-21 20:15:21,521::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-91::DEBUG::2015-10-21 20:15:22,045::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-63::DEBUG::2015-10-21 20:15:22,878::fileSD::262::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/esther.joris2k.nl:_mnt_data_iso/2cee08e0-e675-480a-903c-61f5fe244841/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-63::DEBUG::2015-10-21 20:15:22,887::fileSD::262::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n354 bytes (354 B) copied, 8.1137e-05 s, 4.4 MB/s\n'; <rc> = 0
Thread-101::DEBUG::2015-10-21 20:15:23,046::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-123::DEBUG::2015-10-21 20:15:23,047::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-124::DEBUG::2015-10-21 20:15:23,098::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-89::DEBUG::2015-10-21 20:15:23,177::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
JsonRpc (StompReactor)::DEBUG::2015-10-21 20:15:23,479::stompReactor::98::Broker.StompAdapter::(handle_frame) Handling message <StompFrame command='SEND'>
JsonRpcServer::DEBUG::2015-10-21 20:15:23,480::__init__::530::jsonrpc.JsonRpcServer::(serve_requests) Waiting for request
Thread-32518::DEBUG::2015-10-21 20:15:23,486::stompReactor::163::yajsonrpc.StompServer::(send) Sending response
Thread-100::DEBUG::2015-10-21 20:15:23,916::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-96::DEBUG::2015-10-21 20:15:23,959::task::595::Storage.TaskManager.Task::(_updateState) Task=`de5c502e-a30a-4ae1-86ce-f0ddf21a6660`::moving from state init -> state preparing
Thread-96::INFO::2015-10-21 20:15:23,959::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b', spUUID='c3715f80-6435-45b6-94c2-a9a2869cd059', imgUUID='b3fcd80f-a69e-4796-a675-5c843541a463', volUUID='0a597365-6b76-4f35-bc14-1b3f7db7542f', options=None)
Thread-96::INFO::2015-10-21 20:15:23,961::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '1840160768', 'apparentsize': '2147483648'}
Thread-96::DEBUG::2015-10-21 20:15:23,961::task::1191::Storage.TaskManager.Task::(prepare) Task=`de5c502e-a30a-4ae1-86ce-f0ddf21a6660`::finished: {'truesize': '1840160768', 'apparentsize': '2147483648'}
Thread-96::DEBUG::2015-10-21 20:15:23,961::task::595::Storage.TaskManager.Task::(_updateState) Task=`de5c502e-a30a-4ae1-86ce-f0ddf21a6660`::moving from state preparing -> state finished
Thread-96::DEBUG::2015-10-21 20:15:23,961::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-96::DEBUG::2015-10-21 20:15:23,961::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-96::DEBUG::2015-10-21 20:15:23,961::task::993::Storage.TaskManager.Task::(_decref) Task=`de5c502e-a30a-4ae1-86ce-f0ddf21a6660`::ref 0 aborting False
Thread-96::DEBUG::2015-10-21 20:15:23,961::task::595::Storage.TaskManager.Task::(_updateState) Task=`bba5d995-9ca8-4691-ba83-b99b0944915c`::moving from state init -> state preparing
Thread-96::INFO::2015-10-21 20:15:23,961::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b', spUUID='c3715f80-6435-45b6-94c2-a9a2869cd059', imgUUID='c5ab753b-b977-4242-a390-158b7997491e', volUUID='aca37160-bfd8-4c69-8295-432ef46168fa', options=None)
Thread-96::INFO::2015-10-21 20:15:23,963::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '573632512', 'apparentsize': '16106127360'}
Thread-96::DEBUG::2015-10-21 20:15:23,963::task::1191::Storage.TaskManager.Task::(prepare) Task=`bba5d995-9ca8-4691-ba83-b99b0944915c`::finished: {'truesize': '573632512', 'apparentsize': '16106127360'}
Thread-96::DEBUG::2015-10-21 20:15:23,963::task::595::Storage.TaskManager.Task::(_updateState) Task=`bba5d995-9ca8-4691-ba83-b99b0944915c`::moving from state preparing -> state finished
Thread-96::DEBUG::2015-10-21 20:15:23,963::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-96::DEBUG::2015-10-21 20:15:23,963::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-96::DEBUG::2015-10-21 20:15:23,963::task::993::Storage.TaskManager.Task::(_decref) Task=`bba5d995-9ca8-4691-ba83-b99b0944915c`::ref 0 aborting False
Thread-96::DEBUG::2015-10-21 20:15:23,963::task::595::Storage.TaskManager.Task::(_updateState) Task=`0e4bc24d-6b47-42cb-bfdb-38c0d5451147`::moving from state init -> state preparing
Thread-96::INFO::2015-10-21 20:15:23,963::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='e1826a4b-eeb8-4ec3-bb6b-ab845d3feb85', spUUID='c3715f80-6435-45b6-94c2-a9a2869cd059', imgUUID='07028bc0-ccd2-4f55-83cf-0a451c10b3c7', volUUID='54b5deaa-d659-4012-ad95-f0fda0d3f1c3', options=None)
Thread-96::INFO::2015-10-21 20:15:23,965::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '108101632', 'apparentsize': '2147483648'}
Thread-96::DEBUG::2015-10-21 20:15:23,965::task::1191::Storage.TaskManager.Task::(prepare) Task=`0e4bc24d-6b47-42cb-bfdb-38c0d5451147`::finished: {'truesize': '108101632', 'apparentsize': '2147483648'}
Thread-96::DEBUG::2015-10-21 20:15:23,965::task::595::Storage.TaskManager.Task::(_updateState) Task=`0e4bc24d-6b47-42cb-bfdb-38c0d5451147`::moving from state preparing -> state finished
Thread-96::DEBUG::2015-10-21 20:15:23,965::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-96::DEBUG::2015-10-21 20:15:23,965::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-96::DEBUG::2015-10-21 20:15:23,965::task::993::Storage.TaskManager.Task::(_decref) Task=`0e4bc24d-6b47-42cb-bfdb-38c0d5451147`::ref 0 aborting False
Thread-96::DEBUG::2015-10-21 20:15:23,965::task::595::Storage.TaskManager.Task::(_updateState) Task=`228111f9-3083-4506-b6fc-5beea8e54d18`::moving from state init -> state preparing
Thread-96::INFO::2015-10-21 20:15:23,965::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b', spUUID='c3715f80-6435-45b6-94c2-a9a2869cd059', imgUUID='25b0a2a3-e00b-4580-8f26-31f054090e27', volUUID='283399fd-c70d-44c3-9465-0f22d5478302', options=None)
Thread-96::INFO::2015-10-21 20:15:23,966::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '1073745920', 'apparentsize': '1073741824'}
Thread-96::DEBUG::2015-10-21 20:15:23,966::task::1191::Storage.TaskManager.Task::(prepare) Task=`228111f9-3083-4506-b6fc-5beea8e54d18`::finished: {'truesize': '1073745920', 'apparentsize': '1073741824'}
Thread-96::DEBUG::2015-10-21 20:15:23,967::task::595::Storage.TaskManager.Task::(_updateState) Task=`228111f9-3083-4506-b6fc-5beea8e54d18`::moving from state preparing -> state finished
Thread-96::DEBUG::2015-10-21 20:15:23,967::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-96::DEBUG::2015-10-21 20:15:23,967::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-96::DEBUG::2015-10-21 20:15:23,967::task::993::Storage.TaskManager.Task::(_decref) Task=`228111f9-3083-4506-b6fc-5beea8e54d18`::ref 0 aborting False
Thread-96::DEBUG::2015-10-21 20:15:24,044::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-126::DEBUG::2015-10-21 20:15:24,648::task::595::Storage.TaskManager.Task::(_updateState) Task=`add007a7-a51f-4b59-a4b1-771b623a9b07`::moving from state init -> state preparing
Thread-126::INFO::2015-10-21 20:15:24,648::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b', spUUID='c3715f80-6435-45b6-94c2-a9a2869cd059', imgUUID='0aa7f0d5-22b3-4ff1-9729-ee5f0dd75c71', volUUID='99cbe14c-c7ac-4a99-b86a-88743f221bdb', options=None)
Thread-126::INFO::2015-10-21 20:15:24,651::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '2147487744', 'apparentsize': '2147483648'}
Thread-126::DEBUG::2015-10-21 20:15:24,652::task::1191::Storage.TaskManager.Task::(prepare) Task=`add007a7-a51f-4b59-a4b1-771b623a9b07`::finished: {'truesize': '2147487744', 'apparentsize': '2147483648'}
Thread-126::DEBUG::2015-10-21 20:15:24,652::task::595::Storage.TaskManager.Task::(_updateState) Task=`add007a7-a51f-4b59-a4b1-771b623a9b07`::moving from state preparing -> state finished
Thread-126::DEBUG::2015-10-21 20:15:24,652::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-126::DEBUG::2015-10-21 20:15:24,653::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-126::DEBUG::2015-10-21 20:15:24,653::task::993::Storage.TaskManager.Task::(_decref) Task=`add007a7-a51f-4b59-a4b1-771b623a9b07`::ref 0 aborting False
Thread-126::DEBUG::2015-10-21 20:15:24,654::task::595::Storage.TaskManager.Task::(_updateState) Task=`3fe6b1e8-d25e-46f9-9041-6a2c55d3fcd6`::moving from state init -> state preparing
Thread-126::INFO::2015-10-21 20:15:24,655::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b', spUUID='c3715f80-6435-45b6-94c2-a9a2869cd059', imgUUID='0cb2c393-77d5-4973-b7fc-d9c430b63153', volUUID='f7a18dc5-f9c3-434b-8253-dc3dab2b1b5f', options=None)
Thread-126::INFO::2015-10-21 20:15:24,663::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '195683610624', 'apparentsize': '268435456000'}
Thread-126::DEBUG::2015-10-21 20:15:24,664::task::1191::Storage.TaskManager.Task::(prepare) Task=`3fe6b1e8-d25e-46f9-9041-6a2c55d3fcd6`::finished: {'truesize': '195683610624', 'apparentsize': '268435456000'}
Thread-126::DEBUG::2015-10-21 20:15:24,664::task::595::Storage.TaskManager.Task::(_updateState) Task=`3fe6b1e8-d25e-46f9-9041-6a2c55d3fcd6`::moving from state preparing -> state finished
Thread-126::DEBUG::2015-10-21 20:15:24,665::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-126::DEBUG::2015-10-21 20:15:24,665::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-126::DEBUG::2015-10-21 20:15:24,666::task::993::Storage.TaskManager.Task::(_decref) Task=`3fe6b1e8-d25e-46f9-9041-6a2c55d3fcd6`::ref 0 aborting False
Thread-126::DEBUG::2015-10-21 20:15:24,666::task::595::Storage.TaskManager.Task::(_updateState) Task=`3e719ef5-438a-43fc-9629-f7031d4c5c91`::moving from state init -> state preparing
Thread-126::INFO::2015-10-21 20:15:24,667::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b', spUUID='c3715f80-6435-45b6-94c2-a9a2869cd059', imgUUID='5b389afe-0f39-42c0-a97c-5eb8a68a531a', volUUID='5b2f56d4-ff1b-421e-bf02-617c7b4ff624', options=None)
Thread-126::INFO::2015-10-21 20:15:24,670::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '212992', 'apparentsize': '1073741824'}
Thread-126::DEBUG::2015-10-21 20:15:24,670::task::1191::Storage.TaskManager.Task::(prepare) Task=`3e719ef5-438a-43fc-9629-f7031d4c5c91`::finished: {'truesize': '212992', 'apparentsize': '1073741824'}
Thread-126::DEBUG::2015-10-21 20:15:24,670::task::595::Storage.TaskManager.Task::(_updateState) Task=`3e719ef5-438a-43fc-9629-f7031d4c5c91`::moving from state preparing -> state finished
Thread-126::DEBUG::2015-10-21 20:15:24,670::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-126::DEBUG::2015-10-21 20:15:24,671::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-126::DEBUG::2015-10-21 20:15:24,671::task::993::Storage.TaskManager.Task::(_decref) Task=`3e719ef5-438a-43fc-9629-f7031d4c5c91`::ref 0 aborting False
Thread-126::DEBUG::2015-10-21 20:15:24,671::task::595::Storage.TaskManager.Task::(_updateState) Task=`4a243dee-cb44-42d7-bf2a-60590acf77de`::moving from state init -> state preparing
Thread-126::INFO::2015-10-21 20:15:24,671::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b', spUUID='c3715f80-6435-45b6-94c2-a9a2869cd059', imgUUID='0862f536-43b1-4166-83c8-4e6aae61c8ce', volUUID='e11ce90f-b9d9-44d5-83aa-f725c4144ba6', options=None)
Thread-126::INFO::2015-10-21 20:15:24,672::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '1073745920', 'apparentsize': '1073741824'}
Thread-126::DEBUG::2015-10-21 20:15:24,672::task::1191::Storage.TaskManager.Task::(prepare) Task=`4a243dee-cb44-42d7-bf2a-60590acf77de`::finished: {'truesize': '1073745920', 'apparentsize': '1073741824'}
Thread-126::DEBUG::2015-10-21 20:15:24,672::task::595::Storage.TaskManager.Task::(_updateState) Task=`4a243dee-cb44-42d7-bf2a-60590acf77de`::moving from state preparing -> state finished
Thread-126::DEBUG::2015-10-21 20:15:24,672::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-126::DEBUG::2015-10-21 20:15:24,672::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-126::DEBUG::2015-10-21 20:15:24,672::task::993::Storage.TaskManager.Task::(_decref) Task=`4a243dee-cb44-42d7-bf2a-60590acf77de`::ref 0 aborting False
Thread-126::DEBUG::2015-10-21 20:15:24,673::task::595::Storage.TaskManager.Task::(_updateState) Task=`cc323363-dc8a-4ac1-8a77-b920b38da07e`::moving from state init -> state preparing
Thread-126::INFO::2015-10-21 20:15:24,673::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='e1826a4b-eeb8-4ec3-bb6b-ab845d3feb85', spUUID='c3715f80-6435-45b6-94c2-a9a2869cd059', imgUUID='4cc5c1c1-1296-40ed-9435-037f324508bc', volUUID='98af0ff7-4868-41f4-9d52-1479c2983cc4', options=None)
Thread-126::INFO::2015-10-21 20:15:24,674::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '10720149504', 'apparentsize': '10737418240'}
Thread-126::DEBUG::2015-10-21 20:15:24,674::task::1191::Storage.TaskManager.Task::(prepare) Task=`cc323363-dc8a-4ac1-8a77-b920b38da07e`::finished: {'truesize': '10720149504', 'apparentsize': '10737418240'}
Thread-126::DEBUG::2015-10-21 20:15:24,674::task::595::Storage.TaskManager.Task::(_updateState) Task=`cc323363-dc8a-4ac1-8a77-b920b38da07e`::moving from state preparing -> state finished
Thread-126::DEBUG::2015-10-21 20:15:24,674::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-126::DEBUG::2015-10-21 20:15:24,674::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-126::DEBUG::2015-10-21 20:15:24,674::task::993::Storage.TaskManager.Task::(_decref) Task=`cc323363-dc8a-4ac1-8a77-b920b38da07e`::ref 0 aborting False
Thread-126::DEBUG::2015-10-21 20:15:24,674::task::595::Storage.TaskManager.Task::(_updateState) Task=`7e810814-6bab-4b76-b763-521e5009aca6`::moving from state init -> state preparing
Thread-126::INFO::2015-10-21 20:15:24,674::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b', spUUID='c3715f80-6435-45b6-94c2-a9a2869cd059', imgUUID='e896c805-a5c3-4b8a-9a49-778acf73c06a', volUUID='a324e8f7-9430-4a5b-b822-55e18384e9f4', options=None)
Thread-126::INFO::2015-10-21 20:15:24,675::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '214323482624', 'apparentsize': '214748364800'}
Thread-126::DEBUG::2015-10-21 20:15:24,676::task::1191::Storage.TaskManager.Task::(prepare) Task=`7e810814-6bab-4b76-b763-521e5009aca6`::finished: {'truesize': '214323482624', 'apparentsize': '214748364800'}
Thread-126::DEBUG::2015-10-21 20:15:24,676::task::595::Storage.TaskManager.Task::(_updateState) Task=`7e810814-6bab-4b76-b763-521e5009aca6`::moving from state preparing -> state finished
Thread-126::DEBUG::2015-10-21 20:15:24,676::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-126::DEBUG::2015-10-21 20:15:24,676::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-126::DEBUG::2015-10-21 20:15:24,676::task::993::Storage.TaskManager.Task::(_decref) Task=`7e810814-6bab-4b76-b763-521e5009aca6`::ref 0 aborting False
Thread-126::DEBUG::2015-10-21 20:15:24,676::task::595::Storage.TaskManager.Task::(_updateState) Task=`bff67ca4-703f-413e-992b-4fffe02c9adf`::moving from state init -> state preparing
Thread-126::INFO::2015-10-21 20:15:24,676::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='b6901ec1-7992-4ff8-a728-08bc47103f67', spUUID='c3715f80-6435-45b6-94c2-a9a2869cd059', imgUUID='66d7b3d6-701b-489a-a9b5-0e2eeab1fcd1', volUUID='49f7819f-9748-4eb6-9e6c-5a5ee843bcd0', options=None)
Thread-126::INFO::2015-10-21 20:15:24,677::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '986710450176', 'apparentsize': '1288490188800'}
Thread-126::DEBUG::2015-10-21 20:15:24,677::task::1191::Storage.TaskManager.Task::(prepare) Task=`bff67ca4-703f-413e-992b-4fffe02c9adf`::finished: {'truesize': '986710450176', 'apparentsize': '1288490188800'}
Thread-126::DEBUG::2015-10-21 20:15:24,677::task::595::Storage.TaskManager.Task::(_updateState) Task=`bff67ca4-703f-413e-992b-4fffe02c9adf`::moving from state preparing -> state finished
Thread-126::DEBUG::2015-10-21 20:15:24,677::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-126::DEBUG::2015-10-21 20:15:24,677::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-126::DEBUG::2015-10-21 20:15:24,677::task::993::Storage.TaskManager.Task::(_decref) Task=`bff67ca4-703f-413e-992b-4fffe02c9adf`::ref 0 aborting False
Thread-126::DEBUG::2015-10-21 20:15:24,678::task::595::Storage.TaskManager.Task::(_updateState) Task=`192ef36e-e9a8-4ec2-9af9-df257f4466c1`::moving from state init -> state preparing
Thread-126::INFO::2015-10-21 20:15:24,678::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='b6901ec1-7992-4ff8-a728-08bc47103f67', spUUID='c3715f80-6435-45b6-94c2-a9a2869cd059', imgUUID='3aa38cf5-8185-448d-8238-5aaad67d7d83', volUUID='be32dd6c-51a4-4247-b4ba-7dd6257ee17a', options=None)
Thread-126::INFO::2015-10-21 20:15:24,679::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '109821755392', 'apparentsize': '139586437120'}
Thread-126::DEBUG::2015-10-21 20:15:24,679::task::1191::Storage.TaskManager.Task::(prepare) Task=`192ef36e-e9a8-4ec2-9af9-df257f4466c1`::finished: {'truesize': '109821755392', 'apparentsize': '139586437120'}
Thread-126::DEBUG::2015-10-21 20:15:24,679::task::595::Storage.TaskManager.Task::(_updateState) Task=`192ef36e-e9a8-4ec2-9af9-df257f4466c1`::moving from state preparing -> state finished
Thread-126::DEBUG::2015-10-21 20:15:24,679::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-126::DEBUG::2015-10-21 20:15:24,679::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-126::DEBUG::2015-10-21 20:15:24,679::task::993::Storage.TaskManager.Task::(_decref) Task=`192ef36e-e9a8-4ec2-9af9-df257f4466c1`::ref 0 aborting False
Thread-126::DEBUG::2015-10-21 20:15:24,888::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-128::DEBUG::2015-10-21 20:15:25,581::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-127::DEBUG::2015-10-21 20:15:25,629::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-125::DEBUG::2015-10-21 20:15:25,721::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-98::DEBUG::2015-10-21 20:15:25,722::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-102::DEBUG::2015-10-21 20:15:25,751::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
JsonRpc (StompReactor)::DEBUG::2015-10-21 20:15:25,947::stompReactor::98::Broker.StompAdapter::(handle_frame) Handling message <StompFrame command='SEND'>
Thread-32519::DEBUG::2015-10-21 20:15:25,948::__init__::481::jsonrpc.JsonRpcServer::(_serveRequest) Calling 'StoragePool.getSpmStatus' in bridge with {'storagepoolID': 'c3715f80-6435-45b6-94c2-a9a2869cd059'}
JsonRpcServer::DEBUG::2015-10-21 20:15:25,948::__init__::530::jsonrpc.JsonRpcServer::(serve_requests) Waiting for request
Thread-32519::DEBUG::2015-10-21 20:15:25,949::task::595::Storage.TaskManager.Task::(_updateState) Task=`1102a257-f209-4172-a588-821a8ea69f41`::moving from state init -> state preparing
Thread-32519::INFO::2015-10-21 20:15:25,949::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='c3715f80-6435-45b6-94c2-a9a2869cd059', options=None)
Thread-32519::INFO::2015-10-21 20:15:25,950::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': -1}}
Thread-32519::DEBUG::2015-10-21 20:15:25,950::task::1191::Storage.TaskManager.Task::(prepare) Task=`1102a257-f209-4172-a588-821a8ea69f41`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': -1}}
Thread-32519::DEBUG::2015-10-21 20:15:25,950::task::595::Storage.TaskManager.Task::(_updateState) Task=`1102a257-f209-4172-a588-821a8ea69f41`::moving from state preparing -> state finished
Thread-32519::DEBUG::2015-10-21 20:15:25,950::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-32519::DEBUG::2015-10-21 20:15:25,950::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-32519::DEBUG::2015-10-21 20:15:25,950::task::993::Storage.TaskManager.Task::(_decref) Task=`1102a257-f209-4172-a588-821a8ea69f41`::ref 0 aborting False
Thread-32519::DEBUG::2015-10-21 20:15:25,950::__init__::514::jsonrpc.JsonRpcServer::(_serveRequest) Return 'StoragePool.getSpmStatus' in bridge with {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': -1}
Thread-32519::DEBUG::2015-10-21 20:15:25,950::stompReactor::163::yajsonrpc.StompServer::(send) Sending response
JsonRpc (StompReactor)::DEBUG::2015-10-21 20:15:26,016::stompReactor::98::Broker.StompAdapter::(handle_frame) Handling message <StompFrame command='SEND'>
JsonRpcServer::DEBUG::2015-10-21 20:15:26,017::__init__::530::jsonrpc.JsonRpcServer::(serve_requests) Waiting for request
Thread-32520::DEBUG::2015-10-21 20:15:26,017::__init__::481::jsonrpc.JsonRpcServer::(_serveRequest) Calling 'StoragePool.getInfo' in bridge with {'storagepoolID': 'c3715f80-6435-45b6-94c2-a9a2869cd059'}
Thread-32520::DEBUG::2015-10-21 20:15:26,018::task::595::Storage.TaskManager.Task::(_updateState) Task=`bdec8cb7-f682-4d41-abd3-43964dd0bd69`::moving from state init -> state preparing
Thread-32520::INFO::2015-10-21 20:15:26,018::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='c3715f80-6435-45b6-94c2-a9a2869cd059', options=None)
Thread-32520::DEBUG::2015-10-21 20:15:26,018::resourceManager::198::Storage.ResourceManager.Request::(__init__) ResName=`Storage.c3715f80-6435-45b6-94c2-a9a2869cd059`ReqID=`4c9a863d-a36c-4881-af8e-2df96efdd135`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2632' at 'getStoragePoolInfo'
Thread-32520::DEBUG::2015-10-21 20:15:26,018::resourceManager::542::Storage.ResourceManager::(registerResource) Trying to register resource 'Storage.c3715f80-6435-45b6-94c2-a9a2869cd059' for lock type 'shared'
Thread-32520::DEBUG::2015-10-21 20:15:26,018::resourceManager::601::Storage.ResourceManager::(registerResource) Resource 'Storage.c3715f80-6435-45b6-94c2-a9a2869cd059' is free. Now locking as 'shared' (1 active user)
Thread-32520::DEBUG::2015-10-21 20:15:26,018::resourceManager::238::Storage.ResourceManager.Request::(grant) ResName=`Storage.c3715f80-6435-45b6-94c2-a9a2869cd059`ReqID=`4c9a863d-a36c-4881-af8e-2df96efdd135`::Granted request
Thread-32520::DEBUG::2015-10-21 20:15:26,019::task::827::Storage.TaskManager.Task::(resourceAcquired) Task=`bdec8cb7-f682-4d41-abd3-43964dd0bd69`::_resourcesAcquired: Storage.c3715f80-6435-45b6-94c2-a9a2869cd059 (shared)
Thread-32520::DEBUG::2015-10-21 20:15:26,019::task::993::Storage.TaskManager.Task::(_decref) Task=`bdec8cb7-f682-4d41-abd3-43964dd0bd69`::ref 1 aborting False
Thread-32520::INFO::2015-10-21 20:15:26,019::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'No Description', 'isoprefix': u'/rhev/data-center/mnt/esther.joris2k.nl:_mnt_data_iso/2cee08e0-e675-480a-903c-61f5fe244841/images/11111111-1111-1111-1111-111111111111', 'pool_status': 'connected', 'lver': -1, 'domains': '2cee08e0-e675-480a-903c-61f5fe244841:Active,8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b:Active,b6901ec1-7992-4ff8-a728-08bc47103f67:Active,e1826a4b-eeb8-4ec3-bb6b-ab845d3feb85:Active', 'master_uuid': u'8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b', 'version': '3', 'spm_id': 1, 'type': 'LOCALFS', 'master_ver': 1}, 'dominfo': {'2cee08e0-e675-480a-903c-61f5fe244841': {'status': 'Active', 'diskfree': '266550116352', 'isoprefix': u'/rhev/data-center/mnt/esther.joris2k.nl:_mnt_data_iso/2cee08e0-e675-480a-903c-61f5fe244841/images/11111111-1111-1111-1111-111111111111', 'alerts': [], 'disktotal': '938684186624', 'version': 0}, '8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b': {'status': 'Active', 'diskfree': '266549284864', 'isoprefix': '', 'alerts': [], 'disktotal': '938683396096', 'version': 3}, 'b6901ec1-7992-4ff8-a728-08bc47103f67': {'status': 'Active', 'diskfree': '379594899456', 'isoprefix': '', 'alerts': [], 'disktotal': '1476210552832', 'version': 3}, 'e1826a4b-eeb8-4ec3-bb6b-ab845d3feb85': {'status': 'Active', 'diskfree': '136929796096', 'isoprefix': '', 'alerts': [], 'disktotal': '147831037952', 'version': 3}}}
Thread-32520::DEBUG::2015-10-21 20:15:26,019::task::1191::Storage.TaskManager.Task::(prepare) Task=`bdec8cb7-f682-4d41-abd3-43964dd0bd69`::finished: {'info': {'name': 'No Description', 'isoprefix': u'/rhev/data-center/mnt/esther.joris2k.nl:_mnt_data_iso/2cee08e0-e675-480a-903c-61f5fe244841/images/11111111-1111-1111-1111-111111111111', 'pool_status': 'connected', 'lver': -1, 'domains': '2cee08e0-e675-480a-903c-61f5fe244841:Active,8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b:Active,b6901ec1-7992-4ff8-a728-08bc47103f67:Active,e1826a4b-eeb8-4ec3-bb6b-ab845d3feb85:Active', 'master_uuid': u'8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b', 'version': '3', 'spm_id': 1, 'type': 'LOCALFS', 'master_ver': 1}, 'dominfo': {'2cee08e0-e675-480a-903c-61f5fe244841': {'status': 'Active', 'diskfree': '266550116352', 'isoprefix': u'/rhev/data-center/mnt/esther.joris2k.nl:_mnt_data_iso/2cee08e0-e675-480a-903c-61f5fe244841/images/11111111-1111-1111-1111-111111111111', 'alerts': [], 'disktotal': '938684186624', 'version': 0}, '8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b': {'status': 'Active', 'diskfree': '266549284864', 'isoprefix': '', 'alerts': [], 'disktotal': '938683396096', 'version': 3}, 'b6901ec1-7992-4ff8-a728-08bc47103f67': {'status': 'Active', 'diskfree': '379594899456', 'isoprefix': '', 'alerts': [], 'disktotal': '1476210552832', 'version': 3}, 'e1826a4b-eeb8-4ec3-bb6b-ab845d3feb85': {'status': 'Active', 'diskfree': '136929796096', 'isoprefix': '', 'alerts': [], 'disktotal': '147831037952', 'version': 3}}}
Thread-32520::DEBUG::2015-10-21 20:15:26,019::task::595::Storage.TaskManager.Task::(_updateState) Task=`bdec8cb7-f682-4d41-abd3-43964dd0bd69`::moving from state preparing -> state finished
Thread-32520::DEBUG::2015-10-21 20:15:26,019::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.c3715f80-6435-45b6-94c2-a9a2869cd059': < ResourceRef 'Storage.c3715f80-6435-45b6-94c2-a9a2869cd059', isValid: 'True' obj: 'None'>}
Thread-32520::DEBUG::2015-10-21 20:15:26,019::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-32520::DEBUG::2015-10-21 20:15:26,019::resourceManager::616::Storage.ResourceManager::(releaseResource) Trying to release resource 'Storage.c3715f80-6435-45b6-94c2-a9a2869cd059'
Thread-32520::DEBUG::2015-10-21 20:15:26,020::resourceManager::635::Storage.ResourceManager::(releaseResource) Released resource 'Storage.c3715f80-6435-45b6-94c2-a9a2869cd059' (0 active users)
Thread-32520::DEBUG::2015-10-21 20:15:26,020::resourceManager::641::Storage.ResourceManager::(releaseResource) Resource 'Storage.c3715f80-6435-45b6-94c2-a9a2869cd059' is free, finding out if anyone is waiting for it.
Thread-32520::DEBUG::2015-10-21 20:15:26,020::resourceManager::649::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'Storage.c3715f80-6435-45b6-94c2-a9a2869cd059', Clearing records.
Thread-32520::DEBUG::2015-10-21 20:15:26,020::task::993::Storage.TaskManager.Task::(_decref) Task=`bdec8cb7-f682-4d41-abd3-43964dd0bd69`::ref 0 aborting False
Thread-32520::DEBUG::2015-10-21 20:15:26,020::__init__::514::jsonrpc.JsonRpcServer::(_serveRequest) Return 'StoragePool.getInfo' in bridge with {'info': {'name': 'No Description', 'isoprefix': u'/rhev/data-center/mnt/esther.joris2k.nl:_mnt_data_iso/2cee08e0-e675-480a-903c-61f5fe244841/images/11111111-1111-1111-1111-111111111111', 'pool_status': 'connected', 'lver': -1, 'domains': '2cee08e0-e675-480a-903c-61f5fe244841:Active,8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b:Active,b6901ec1-7992-4ff8-a728-08bc47103f67:Active,e1826a4b-eeb8-4ec3-bb6b-ab845d3feb85:Active', 'master_uuid': u'8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b', 'version': '3', 'spm_id': 1, 'type': 'LOCALFS', 'master_ver': 1}, 'dominfo': {'2cee08e0-e675-480a-903c-61f5fe244841': {'status': 'Active', 'diskfree': '266550116352', 'isoprefix': u'/rhev/data-center/mnt/esther.joris2k.nl:_mnt_data_iso/2cee08e0-e675-480a-903c-61f5fe244841/images/11111111-1111-1111-1111-111111111111', 'alerts': [], 'disktotal': '938684186624', 'version': 0}, '8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b': {'status': 'Active', 'diskfree': '266549284864', 'isoprefix': '', 'alerts': [], 'disktotal': '938683396096', 'version': 3}, 'b6901ec1-7992-4ff8-a728-08bc47103f67': {'status': 'Active', 'diskfree': '379594899456', 'isoprefix': '', 'alerts': [], 'disktotal': '1476210552832', 'version': 3}, 'e1826a4b-eeb8-4ec3-bb6b-ab845d3feb85': {'status': 'Active', 'diskfree': '136929796096', 'isoprefix': '', 'alerts': [], 'disktotal': '147831037952', 'version': 3}}}
Thread-32520::DEBUG::2015-10-21 20:15:26,020::stompReactor::163::yajsonrpc.StompServer::(send) Sending response
Thread-64::DEBUG::2015-10-21 20:15:26,345::fileSD::262::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/_mnt_data_storage/8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-64::DEBUG::2015-10-21 20:15:26,353::fileSD::262::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n513 bytes (513 B) copied, 0.000200826 s, 2.6 MB/s\n'; <rc> = 0
JsonRpc (StompReactor)::DEBUG::2015-10-21 20:15:26,492::stompReactor::98::Broker.StompAdapter::(handle_frame) Handling message <StompFrame command='SEND'>
JsonRpcServer::DEBUG::2015-10-21 20:15:26,493::__init__::530::jsonrpc.JsonRpcServer::(serve_requests) Waiting for request
Thread-32521::DEBUG::2015-10-21 20:15:26,500::stompReactor::163::yajsonrpc.StompServer::(send) Sending response
Thread-92::DEBUG::2015-10-21 20:15:27,327::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-97::DEBUG::2015-10-21 20:15:27,327::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
JsonRpc (StompReactor)::DEBUG::2015-10-21 20:15:29,505::stompReactor::98::Broker.StompAdapter::(handle_frame) Handling message <StompFrame command='SEND'>
JsonRpcServer::DEBUG::2015-10-21 20:15:29,506::__init__::530::jsonrpc.JsonRpcServer::(serve_requests) Waiting for request
Thread-32522::DEBUG::2015-10-21 20:15:29,511::stompReactor::163::yajsonrpc.StompServer::(send) Sending response
Thread-65::DEBUG::2015-10-21 20:15:29,555::fileSD::262::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/_mnt_data__ssd_storage/e1826a4b-eeb8-4ec3-bb6b-ab845d3feb85/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-65::DEBUG::2015-10-21 20:15:29,563::fileSD::262::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n333 bytes (333 B) copied, 0.000209755 s, 1.6 MB/s\n'; <rc> = 0
Thread-66::DEBUG::2015-10-21 20:15:29,607::fileSD::262::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/_mnt_data__bulk_storage/b6901ec1-7992-4ff8-a728-08bc47103f67/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-66::DEBUG::2015-10-21 20:15:29,616::fileSD::262::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n335 bytes (335 B) copied, 0.00019051 s, 1.8 MB/s\n'; <rc> = 0
JsonRpc (StompReactor)::DEBUG::2015-10-21 20:15:32,516::stompReactor::98::Broker.StompAdapter::(handle_frame) Handling message <StompFrame command='SEND'>
JsonRpcServer::DEBUG::2015-10-21 20:15:32,518::__init__::530::jsonrpc.JsonRpcServer::(serve_requests) Waiting for request
Thread-32523::DEBUG::2015-10-21 20:15:32,523::task::595::Storage.TaskManager.Task::(_updateState) Task=`9ef0236e-33a8-4817-84e2-64ba25f8c16e`::moving from state init -> state preparing
Thread-32523::INFO::2015-10-21 20:15:32,523::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-32523::INFO::2015-10-21 20:15:32,524::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'2cee08e0-e675-480a-903c-61f5fe244841': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '8.1137e-05', 'lastCheck': '9.6', 'valid': True}, '8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b': {'code': 0, 'actual': True, 'version': 3, 'acquired': True, 'delay': '0.000200826', 'lastCheck': '6.2', 'valid': True}, 'b6901ec1-7992-4ff8-a728-08bc47103f67': {'code': 0, 'actual': True, 'version': 3, 'acquired': True, 'delay': '0.00019051', 'lastCheck': '2.9', 'valid': True}, 'e1826a4b-eeb8-4ec3-bb6b-ab845d3feb85': {'code': 0, 'actual': True, 'version': 3, 'acquired': True, 'delay': '0.000209755', 'lastCheck': '3.0', 'valid': True}}
Thread-32523::DEBUG::2015-10-21 20:15:32,525::task::1191::Storage.TaskManager.Task::(prepare) Task=`9ef0236e-33a8-4817-84e2-64ba25f8c16e`::finished: {'2cee08e0-e675-480a-903c-61f5fe244841': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '8.1137e-05', 'lastCheck': '9.6', 'valid': True}, '8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b': {'code': 0, 'actual': True, 'version': 3, 'acquired': True, 'delay': '0.000200826', 'lastCheck': '6.2', 'valid': True}, 'b6901ec1-7992-4ff8-a728-08bc47103f67': {'code': 0, 'actual': True, 'version': 3, 'acquired': True, 'delay': '0.00019051', 'lastCheck': '2.9', 'valid': True}, 'e1826a4b-eeb8-4ec3-bb6b-ab845d3feb85': {'code': 0, 'actual': True, 'version': 3, 'acquired': True, 'delay': '0.000209755', 'lastCheck': '3.0', 'valid': True}}
Thread-32523::DEBUG::2015-10-21 20:15:32,525::task::595::Storage.TaskManager.Task::(_updateState) Task=`9ef0236e-33a8-4817-84e2-64ba25f8c16e`::moving from state preparing -> state finished
Thread-32523::DEBUG::2015-10-21 20:15:32,526::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-32523::DEBUG::2015-10-21 20:15:32,526::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-32523::DEBUG::2015-10-21 20:15:32,526::task::993::Storage.TaskManager.Task::(_decref) Task=`9ef0236e-33a8-4817-84e2-64ba25f8c16e`::ref 0 aborting False
Thread-32523::DEBUG::2015-10-21 20:15:32,537::stompReactor::163::yajsonrpc.StompServer::(send) Sending response
JsonRpc (StompReactor)::DEBUG::2015-10-21 20:15:32,545::stompReactor::98::Broker.StompAdapter::(handle_frame) Handling message <StompFrame command='SEND'>
JsonRpcServer::DEBUG::2015-10-21 20:15:32,546::__init__::530::jsonrpc.JsonRpcServer::(serve_requests) Waiting for request
Thread-32524::DEBUG::2015-10-21 20:15:32,606::stompReactor::163::yajsonrpc.StompServer::(send) Sending response
Thread-63::DEBUG::2015-10-21 20:15:32,890::fileSD::262::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/esther.joris2k.nl:_mnt_data_iso/2cee08e0-e675-480a-903c-61f5fe244841/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-63::DEBUG::2015-10-21 20:15:32,898::fileSD::262::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n354 bytes (354 B) copied, 9.8754e-05 s, 3.6 MB/s\n'; <rc> = 0
JsonRpc (StompReactor)::DEBUG::2015-10-21 20:15:36,019::stompReactor::98::Broker.StompAdapter::(handle_frame) Handling message <StompFrame command='SEND'>
JsonRpcServer::DEBUG::2015-10-21 20:15:36,023::__init__::530::jsonrpc.JsonRpcServer::(serve_requests) Waiting for request
Thread-32525::DEBUG::2015-10-21 20:15:36,030::stompReactor::163::yajsonrpc.StompServer::(send) Sending response
JsonRpc (StompReactor)::DEBUG::2015-10-21 20:15:36,106::stompReactor::98::Broker.StompAdapter::(handle_frame) Handling message <StompFrame command='SEND'>
JsonRpcServer::DEBUG::2015-10-21 20:15:36,107::__init__::530::jsonrpc.JsonRpcServer::(serve_requests) Waiting for request
Thread-32526::DEBUG::2015-10-21 20:15:36,107::__init__::481::jsonrpc.JsonRpcServer::(_serveRequest) Calling 'StoragePool.getSpmStatus' in bridge with {'storagepoolID': 'c3715f80-6435-45b6-94c2-a9a2869cd059'}
Thread-32526::DEBUG::2015-10-21 20:15:36,108::task::595::Storage.TaskManager.Task::(_updateState) Task=`de4ee357-7cb4-4f87-a5fd-c4b83966bbac`::moving from state init -> state preparing
Thread-32526::INFO::2015-10-21 20:15:36,108::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='c3715f80-6435-45b6-94c2-a9a2869cd059', options=None)
Thread-32526::INFO::2015-10-21 20:15:36,108::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': -1}}
Thread-32526::DEBUG::2015-10-21 20:15:36,108::task::1191::Storage.TaskManager.Task::(prepare) Task=`de4ee357-7cb4-4f87-a5fd-c4b83966bbac`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': -1}}
Thread-32526::DEBUG::2015-10-21 20:15:36,108::task::595::Storage.TaskManager.Task::(_updateState) Task=`de4ee357-7cb4-4f87-a5fd-c4b83966bbac`::moving from state preparing -> state finished
Thread-32526::DEBUG::2015-10-21 20:15:36,108::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-32526::DEBUG::2015-10-21 20:15:36,108::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-32526::DEBUG::2015-10-21 20:15:36,109::task::993::Storage.TaskManager.Task::(_decref) Task=`de4ee357-7cb4-4f87-a5fd-c4b83966bbac`::ref 0 aborting False
Thread-32526::DEBUG::2015-10-21 20:15:36,109::__init__::514::jsonrpc.JsonRpcServer::(_serveRequest) Return 'StoragePool.getSpmStatus' in bridge with {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': -1}
Thread-32526::DEBUG::2015-10-21 20:15:36,109::stompReactor::163::yajsonrpc.StompServer::(send) Sending response
JsonRpc (StompReactor)::DEBUG::2015-10-21 20:15:36,132::stompReactor::98::Broker.StompAdapter::(handle_frame) Handling message <StompFrame command='SEND'>
Thread-32527::DEBUG::2015-10-21 20:15:36,133::__init__::481::jsonrpc.JsonRpcServer::(_serveRequest) Calling 'StoragePool.getInfo' in bridge with {'storagepoolID': 'c3715f80-6435-45b6-94c2-a9a2869cd059'}
JsonRpcServer::DEBUG::2015-10-21 20:15:36,133::__init__::530::jsonrpc.JsonRpcServer::(serve_requests) Waiting for request
Thread-32527::DEBUG::2015-10-21 20:15:36,134::task::595::Storage.TaskManager.Task::(_updateState) Task=`527e357f-af37-42c6-9280-ee4e62707ea3`::moving from state init -> state preparing
Thread-32527::INFO::2015-10-21 20:15:36,134::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='c3715f80-6435-45b6-94c2-a9a2869cd059', options=None)
Thread-32527::DEBUG::2015-10-21 20:15:36,134::resourceManager::198::Storage.ResourceManager.Request::(__init__) ResName=`Storage.c3715f80-6435-45b6-94c2-a9a2869cd059`ReqID=`bac01f97-db96-45c7-8063-b992befabdc7`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2632' at 'getStoragePoolInfo'
Thread-32527::DEBUG::2015-10-21 20:15:36,134::resourceManager::542::Storage.ResourceManager::(registerResource) Trying to register resource 'Storage.c3715f80-6435-45b6-94c2-a9a2869cd059' for lock type 'shared'
Thread-32527::DEBUG::2015-10-21 20:15:36,134::resourceManager::601::Storage.ResourceManager::(registerResource) Resource 'Storage.c3715f80-6435-45b6-94c2-a9a2869cd059' is free. Now locking as 'shared' (1 active user)
Thread-32527::DEBUG::2015-10-21 20:15:36,134::resourceManager::238::Storage.ResourceManager.Request::(grant) ResName=`Storage.c3715f80-6435-45b6-94c2-a9a2869cd059`ReqID=`bac01f97-db96-45c7-8063-b992befabdc7`::Granted request
Thread-32527::DEBUG::2015-10-21 20:15:36,134::task::827::Storage.TaskManager.Task::(resourceAcquired) Task=`527e357f-af37-42c6-9280-ee4e62707ea3`::_resourcesAcquired: Storage.c3715f80-6435-45b6-94c2-a9a2869cd059 (shared)
Thread-32527::DEBUG::2015-10-21 20:15:36,135::task::993::Storage.TaskManager.Task::(_decref) Task=`527e357f-af37-42c6-9280-ee4e62707ea3`::ref 1 aborting False
Thread-32527::INFO::2015-10-21 20:15:36,136::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'No Description', 'isoprefix': u'/rhev/data-center/mnt/esther.joris2k.nl:_mnt_data_iso/2cee08e0-e675-480a-903c-61f5fe244841/images/11111111-1111-1111-1111-111111111111', 'pool_status': 'connected', 'lver': -1, 'domains': '2cee08e0-e675-480a-903c-61f5fe244841:Active,8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b:Active,b6901ec1-7992-4ff8-a728-08bc47103f67:Active,e1826a4b-eeb8-4ec3-bb6b-ab845d3feb85:Active', 'master_uuid': u'8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b', 'version': '3', 'spm_id': 1, 'type': 'LOCALFS', 'master_ver': 1}, 'dominfo': {'2cee08e0-e675-480a-903c-61f5fe244841': {'status': 'Active', 'diskfree': '266550116352', 'isoprefix': u'/rhev/data-center/mnt/esther.joris2k.nl:_mnt_data_iso/2cee08e0-e675-480a-903c-61f5fe244841/images/11111111-1111-1111-1111-111111111111', 'alerts': [], 'disktotal': '938684186624', 'version': 0}, '8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b': {'status': 'Active', 'diskfree': '266549284864', 'isoprefix': '', 'alerts': [], 'disktotal': '938683396096', 'version': 3}, 'b6901ec1-7992-4ff8-a728-08bc47103f67': {'status': 'Active', 'diskfree': '379594899456', 'isoprefix': '', 'alerts': [], 'disktotal': '1476210552832', 'version': 3}, 'e1826a4b-eeb8-4ec3-bb6b-ab845d3feb85': {'status': 'Active', 'diskfree': '136929796096', 'isoprefix': '', 'alerts': [], 'disktotal': '147831037952', 'version': 3}}}
Thread-32527::DEBUG::2015-10-21 20:15:36,136::task::1191::Storage.TaskManager.Task::(prepare) Task=`527e357f-af37-42c6-9280-ee4e62707ea3`::finished: {'info': {'name': 'No Description', 'isoprefix': u'/rhev/data-center/mnt/esther.joris2k.nl:_mnt_data_iso/2cee08e0-e675-480a-903c-61f5fe244841/images/11111111-1111-1111-1111-111111111111', 'pool_status': 'connected', 'lver': -1, 'domains': '2cee08e0-e675-480a-903c-61f5fe244841:Active,8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b:Active,b6901ec1-7992-4ff8-a728-08bc47103f67:Active,e1826a4b-eeb8-4ec3-bb6b-ab845d3feb85:Active', 'master_uuid': u'8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b', 'version': '3', 'spm_id': 1, 'type': 'LOCALFS', 'master_ver': 1}, 'dominfo': {'2cee08e0-e675-480a-903c-61f5fe244841': {'status': 'Active', 'diskfree': '266550116352', 'isoprefix': u'/rhev/data-center/mnt/esther.joris2k.nl:_mnt_data_iso/2cee08e0-e675-480a-903c-61f5fe244841/images/11111111-1111-1111-1111-111111111111', 'alerts': [], 'disktotal': '938684186624', 'version': 0}, '8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b': {'status': 'Active', 'diskfree': '266549284864', 'isoprefix': '', 'alerts': [], 'disktotal': '938683396096', 'version': 3}, 'b6901ec1-7992-4ff8-a728-08bc47103f67': {'status': 'Active', 'diskfree': '379594899456', 'isoprefix': '', 'alerts': [], 'disktotal': '1476210552832', 'version': 3}, 'e1826a4b-eeb8-4ec3-bb6b-ab845d3feb85': {'status': 'Active', 'diskfree': '136929796096', 'isoprefix': '', 'alerts': [], 'disktotal': '147831037952', 'version': 3}}}
Thread-32527::DEBUG::2015-10-21 20:15:36,137::task::595::Storage.TaskManager.Task::(_updateState) Task=`527e357f-af37-42c6-9280-ee4e62707ea3`::moving from state preparing -> state finished
Thread-32527::DEBUG::2015-10-21 20:15:36,137::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.c3715f80-6435-45b6-94c2-a9a2869cd059': < ResourceRef 'Storage.c3715f80-6435-45b6-94c2-a9a2869cd059', isValid: 'True' obj: 'None'>}
Thread-32527::DEBUG::2015-10-21 20:15:36,137::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-32527::DEBUG::2015-10-21 20:15:36,137::resourceManager::616::Storage.ResourceManager::(releaseResource) Trying to release resource 'Storage.c3715f80-6435-45b6-94c2-a9a2869cd059'
Thread-32527::DEBUG::2015-10-21 20:15:36,137::resourceManager::635::Storage.ResourceManager::(releaseResource) Released resource 'Storage.c3715f80-6435-45b6-94c2-a9a2869cd059' (0 active users)
Thread-32527::DEBUG::2015-10-21 20:15:36,137::resourceManager::641::Storage.ResourceManager::(releaseResource) Resource 'Storage.c3715f80-6435-45b6-94c2-a9a2869cd059' is free, finding out if anyone is waiting for it.
Thread-32527::DEBUG::2015-10-21 20:15:36,137::resourceManager::649::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'Storage.c3715f80-6435-45b6-94c2-a9a2869cd059', Clearing records.
Thread-32527::DEBUG::2015-10-21 20:15:36,137::task::993::Storage.TaskManager.Task::(_decref) Task=`527e357f-af37-42c6-9280-ee4e62707ea3`::ref 0 aborting False
Thread-32527::DEBUG::2015-10-21 20:15:36,137::__init__::514::jsonrpc.JsonRpcServer::(_serveRequest) Return 'StoragePool.getInfo' in bridge with {'info': {'name': 'No Description', 'isoprefix': u'/rhev/data-center/mnt/esther.joris2k.nl:_mnt_data_iso/2cee08e0-e675-480a-903c-61f5fe244841/images/11111111-1111-1111-1111-111111111111', 'pool_status': 'connected', 'lver': -1, 'domains': '2cee08e0-e675-480a-903c-61f5fe244841:Active,8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b:Active,b6901ec1-7992-4ff8-a728-08bc47103f67:Active,e1826a4b-eeb8-4ec3-bb6b-ab845d3feb85:Active', 'master_uuid': u'8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b', 'version': '3', 'spm_id': 1, 'type': 'LOCALFS', 'master_ver': 1}, 'dominfo': {'2cee08e0-e675-480a-903c-61f5fe244841': {'status': 'Active', 'diskfree': '266550116352', 'isoprefix': u'/rhev/data-center/mnt/esther.joris2k.nl:_mnt_data_iso/2cee08e0-e675-480a-903c-61f5fe244841/images/11111111-1111-1111-1111-111111111111', 'alerts': [], 'disktotal': '938684186624', 'version': 0}, '8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b': {'status': 'Active', 'diskfree': '266549284864', 'isoprefix': '', 'alerts': [], 'disktotal': '938683396096', 'version': 3}, 'b6901ec1-7992-4ff8-a728-08bc47103f67': {'status': 'Active', 'diskfree': '379594899456', 'isoprefix': '', 'alerts': [], 'disktotal': '1476210552832', 'version': 3}, 'e1826a4b-eeb8-4ec3-bb6b-ab845d3feb85': {'status': 'Active', 'diskfree': '136929796096', 'isoprefix': '', 'alerts': [], 'disktotal': '147831037952', 'version': 3}}}
Thread-32527::DEBUG::2015-10-21 20:15:36,137::stompReactor::163::yajsonrpc.StompServer::(send) Sending response
Thread-103::DEBUG::2015-10-21 20:15:36,306::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-64::DEBUG::2015-10-21 20:15:36,357::fileSD::262::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/_mnt_data_storage/8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-64::DEBUG::2015-10-21 20:15:36,370::fileSD::262::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n513 bytes (513 B) copied, 0.000237722 s, 2.2 MB/s\n'; <rc> = 0
Thread-99::DEBUG::2015-10-21 20:15:36,535::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-91::DEBUG::2015-10-21 20:15:37,047::task::595::Storage.TaskManager.Task::(_updateState) Task=`4d2079b0-b40a-470c-9423-f04ae0e66d7b`::moving from state init -> state preparing
Thread-91::INFO::2015-10-21 20:15:37,048::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b', spUUID='c3715f80-6435-45b6-94c2-a9a2869cd059', imgUUID='f9ec6a84-a224-4bde-b2dc-e3e4e4db1b63', volUUID='c17740cf-9c4d-4170-9f24-846d61e9c413', options=None)
Thread-91::INFO::2015-10-21 20:15:37,051::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '4412203008', 'apparentsize': '8589934592'}
Thread-91::DEBUG::2015-10-21 20:15:37,051::task::1191::Storage.TaskManager.Task::(prepare) Task=`4d2079b0-b40a-470c-9423-f04ae0e66d7b`::finished: {'truesize': '4412203008', 'apparentsize': '8589934592'}
Thread-91::DEBUG::2015-10-21 20:15:37,051::task::595::Storage.TaskManager.Task::(_updateState) Task=`4d2079b0-b40a-470c-9423-f04ae0e66d7b`::moving from state preparing -> state finished
Thread-91::DEBUG::2015-10-21 20:15:37,051::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-91::DEBUG::2015-10-21 20:15:37,051::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-91::DEBUG::2015-10-21 20:15:37,051::task::993::Storage.TaskManager.Task::(_decref) Task=`4d2079b0-b40a-470c-9423-f04ae0e66d7b`::ref 0 aborting False
Thread-91::DEBUG::2015-10-21 20:15:37,083::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-123::DEBUG::2015-10-21 20:15:38,073::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-101::DEBUG::2015-10-21 20:15:38,074::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-124::DEBUG::2015-10-21 20:15:38,110::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-89::DEBUG::2015-10-21 20:15:38,196::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-100::DEBUG::2015-10-21 20:15:38,943::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
JsonRpc (StompReactor)::DEBUG::2015-10-21 20:15:39,043::stompReactor::98::Broker.StompAdapter::(handle_frame) Handling message <StompFrame command='SEND'>
JsonRpcServer::DEBUG::2015-10-21 20:15:39,044::__init__::530::jsonrpc.JsonRpcServer::(serve_requests) Waiting for request
Thread-32528::DEBUG::2015-10-21 20:15:39,055::stompReactor::163::yajsonrpc.StompServer::(send) Sending response
Thread-96::DEBUG::2015-10-21 20:15:39,061::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-65::DEBUG::2015-10-21 20:15:39,567::fileSD::262::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/_mnt_data__ssd_storage/e1826a4b-eeb8-4ec3-bb6b-ab845d3feb85/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-65::DEBUG::2015-10-21 20:15:39,577::fileSD::262::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n333 bytes (333 B) copied, 0.000198467 s, 1.7 MB/s\n'; <rc> = 0
Thread-66::DEBUG::2015-10-21 20:15:39,619::fileSD::262::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/_mnt_data__bulk_storage/b6901ec1-7992-4ff8-a728-08bc47103f67/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-66::DEBUG::2015-10-21 20:15:39,637::fileSD::262::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n335 bytes (335 B) copied, 0.000172473 s, 1.9 MB/s\n'; <rc> = 0
Thread-126::DEBUG::2015-10-21 20:15:39,901::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-128::DEBUG::2015-10-21 20:15:40,594::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-127::DEBUG::2015-10-21 20:15:40,646::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-98::DEBUG::2015-10-21 20:15:40,752::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-125::DEBUG::2015-10-21 20:15:40,753::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-102::DEBUG::2015-10-21 20:15:40,763::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
JsonRpc (StompReactor)::DEBUG::2015-10-21 20:15:42,061::stompReactor::98::Broker.StompAdapter::(handle_frame) Handling message <StompFrame command='SEND'>
JsonRpcServer::DEBUG::2015-10-21 20:15:42,062::__init__::530::jsonrpc.JsonRpcServer::(serve_requests) Waiting for request
Thread-32529::DEBUG::2015-10-21 20:15:42,069::stompReactor::163::yajsonrpc.StompServer::(send) Sending response
Thread-92::DEBUG::2015-10-21 20:15:42,329::task::595::Storage.TaskManager.Task::(_updateState) Task=`81bc20b1-dd11-4b84-82da-f63da1112214`::moving from state init -> state preparing
Thread-97::DEBUG::2015-10-21 20:15:42,330::task::595::Storage.TaskManager.Task::(_updateState) Task=`acaa2659-be1e-468e-b06a-28242950d13d`::moving from state init -> state preparing
Thread-92::INFO::2015-10-21 20:15:42,330::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b', spUUID='c3715f80-6435-45b6-94c2-a9a2869cd059', imgUUID='d7a912ee-9a7e-415c-84e9-c250f99c00ad', volUUID='72daf857-252e-42f2-a53f-5e12d8613cba', options=None)
Thread-97::INFO::2015-10-21 20:15:42,330::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b', spUUID='c3715f80-6435-45b6-94c2-a9a2869cd059', imgUUID='a8d19d52-287f-42e0-9422-babce4f31ffd', volUUID='0991d467-9a33-4a71-9f3e-e9bff4a12bd0', options=None)
Thread-92::INFO::2015-10-21 20:15:42,336::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '1909321728', 'apparentsize': '3221225472'}
Thread-92::DEBUG::2015-10-21 20:15:42,338::task::1191::Storage.TaskManager.Task::(prepare) Task=`81bc20b1-dd11-4b84-82da-f63da1112214`::finished: {'truesize': '1909321728', 'apparentsize': '3221225472'}
Thread-92::DEBUG::2015-10-21 20:15:42,339::task::595::Storage.TaskManager.Task::(_updateState) Task=`81bc20b1-dd11-4b84-82da-f63da1112214`::moving from state preparing -> state finished
Thread-92::DEBUG::2015-10-21 20:15:42,340::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-92::DEBUG::2015-10-21 20:15:42,341::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-97::INFO::2015-10-21 20:15:42,341::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '6317817856', 'apparentsize': '6317867008'}
Thread-92::DEBUG::2015-10-21 20:15:42,342::task::993::Storage.TaskManager.Task::(_decref) Task=`81bc20b1-dd11-4b84-82da-f63da1112214`::ref 0 aborting False
Thread-97::DEBUG::2015-10-21 20:15:42,342::task::1191::Storage.TaskManager.Task::(prepare) Task=`acaa2659-be1e-468e-b06a-28242950d13d`::finished: {'truesize': '6317817856', 'apparentsize': '6317867008'}
Thread-97::DEBUG::2015-10-21 20:15:42,343::task::595::Storage.TaskManager.Task::(_updateState) Task=`acaa2659-be1e-468e-b06a-28242950d13d`::moving from state preparing -> state finished
Thread-97::DEBUG::2015-10-21 20:15:42,344::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-97::DEBUG::2015-10-21 20:15:42,344::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-97::DEBUG::2015-10-21 20:15:42,345::task::993::Storage.TaskManager.Task::(_decref) Task=`acaa2659-be1e-468e-b06a-28242950d13d`::ref 0 aborting False
Thread-92::DEBUG::2015-10-21 20:15:42,389::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-97::DEBUG::2015-10-21 20:15:42,390::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-63::DEBUG::2015-10-21 20:15:42,904::fileSD::262::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/esther.joris2k.nl:_mnt_data_iso/2cee08e0-e675-480a-903c-61f5fe244841/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-63::DEBUG::2015-10-21 20:15:42,916::fileSD::262::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n354 bytes (354 B) copied, 0.000105691 s, 3.3 MB/s\n'; <rc> = 0
JsonRpc (StompReactor)::DEBUG::2015-10-21 20:15:45,074::stompReactor::98::Broker.StompAdapter::(handle_frame) Handling message <StompFrame command='SEND'>
JsonRpcServer::DEBUG::2015-10-21 20:15:45,075::__init__::530::jsonrpc.JsonRpcServer::(serve_requests) Waiting for request
Thread-32530::DEBUG::2015-10-21 20:15:45,082::stompReactor::163::yajsonrpc.StompServer::(send) Sending response
JsonRpc (StompReactor)::DEBUG::2015-10-21 20:15:46,183::stompReactor::98::Broker.StompAdapter::(handle_frame) Handling message <StompFrame command='SEND'>
JsonRpcServer::DEBUG::2015-10-21 20:15:46,184::__init__::530::jsonrpc.JsonRpcServer::(serve_requests) Waiting for request
Thread-32531::DEBUG::2015-10-21 20:15:46,184::__init__::481::jsonrpc.JsonRpcServer::(_serveRequest) Calling 'StoragePool.getSpmStatus' in bridge with {'storagepoolID': 'c3715f80-6435-45b6-94c2-a9a2869cd059'}
Thread-32531::DEBUG::2015-10-21 20:15:46,184::task::595::Storage.TaskManager.Task::(_updateState) Task=`7e8a9ec6-7753-457c-bf8e-8924382f9595`::moving from state init -> state preparing
Thread-32531::INFO::2015-10-21 20:15:46,185::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='c3715f80-6435-45b6-94c2-a9a2869cd059', options=None)
Thread-32531::INFO::2015-10-21 20:15:46,185::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': -1}}
Thread-32531::DEBUG::2015-10-21 20:15:46,185::task::1191::Storage.TaskManager.Task::(prepare) Task=`7e8a9ec6-7753-457c-bf8e-8924382f9595`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': -1}}
Thread-32531::DEBUG::2015-10-21 20:15:46,185::task::595::Storage.TaskManager.Task::(_updateState) Task=`7e8a9ec6-7753-457c-bf8e-8924382f9595`::moving from state preparing -> state finished
Thread-32531::DEBUG::2015-10-21 20:15:46,185::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-32531::DEBUG::2015-10-21 20:15:46,185::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-32531::DEBUG::2015-10-21 20:15:46,185::task::993::Storage.TaskManager.Task::(_decref) Task=`7e8a9ec6-7753-457c-bf8e-8924382f9595`::ref 0 aborting False
Thread-32531::DEBUG::2015-10-21 20:15:46,185::__init__::514::jsonrpc.JsonRpcServer::(_serveRequest) Return 'StoragePool.getSpmStatus' in bridge with {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': -1}
Thread-32531::DEBUG::2015-10-21 20:15:46,185::stompReactor::163::yajsonrpc.StompServer::(send) Sending response
JsonRpc (StompReactor)::DEBUG::2015-10-21 20:15:46,220::stompReactor::98::Broker.StompAdapter::(handle_frame) Handling message <StompFrame command='SEND'>
JsonRpcServer::DEBUG::2015-10-21 20:15:46,221::__init__::530::jsonrpc.JsonRpcServer::(serve_requests) Waiting for request
Thread-32532::DEBUG::2015-10-21 20:15:46,221::__init__::481::jsonrpc.JsonRpcServer::(_serveRequest) Calling 'StoragePool.getInfo' in bridge with {'storagepoolID': 'c3715f80-6435-45b6-94c2-a9a2869cd059'}
Thread-32532::DEBUG::2015-10-21 20:15:46,222::task::595::Storage.TaskManager.Task::(_updateState) Task=`21932d0f-0da3-4029-8a90-044060557189`::moving from state init -> state preparing
Thread-32532::INFO::2015-10-21 20:15:46,222::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='c3715f80-6435-45b6-94c2-a9a2869cd059', options=None)
Thread-32532::DEBUG::2015-10-21 20:15:46,222::resourceManager::198::Storage.ResourceManager.Request::(__init__) ResName=`Storage.c3715f80-6435-45b6-94c2-a9a2869cd059`ReqID=`44dd0860-deb8-4581-a7f0-29d045ab92b4`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2632' at 'getStoragePoolInfo'
Thread-32532::DEBUG::2015-10-21 20:15:46,222::resourceManager::542::Storage.ResourceManager::(registerResource) Trying to register resource 'Storage.c3715f80-6435-45b6-94c2-a9a2869cd059' for lock type 'shared'
Thread-32532::DEBUG::2015-10-21 20:15:46,223::resourceManager::601::Storage.ResourceManager::(registerResource) Resource 'Storage.c3715f80-6435-45b6-94c2-a9a2869cd059' is free. Now locking as 'shared' (1 active user)
Thread-32532::DEBUG::2015-10-21 20:15:46,223::resourceManager::238::Storage.ResourceManager.Request::(grant) ResName=`Storage.c3715f80-6435-45b6-94c2-a9a2869cd059`ReqID=`44dd0860-deb8-4581-a7f0-29d045ab92b4`::Granted request
Thread-32532::DEBUG::2015-10-21 20:15:46,223::task::827::Storage.TaskManager.Task::(resourceAcquired) Task=`21932d0f-0da3-4029-8a90-044060557189`::_resourcesAcquired: Storage.c3715f80-6435-45b6-94c2-a9a2869cd059 (shared)
Thread-32532::DEBUG::2015-10-21 20:15:46,223::task::993::Storage.TaskManager.Task::(_decref) Task=`21932d0f-0da3-4029-8a90-044060557189`::ref 1 aborting False
Thread-32532::INFO::2015-10-21 20:15:46,223::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'No Description', 'isoprefix': u'/rhev/data-center/mnt/esther.joris2k.nl:_mnt_data_iso/2cee08e0-e675-480a-903c-61f5fe244841/images/11111111-1111-1111-1111-111111111111', 'pool_status': 'connected', 'lver': -1, 'domains': '2cee08e0-e675-480a-903c-61f5fe244841:Active,8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b:Active,b6901ec1-7992-4ff8-a728-08bc47103f67:Active,e1826a4b-eeb8-4ec3-bb6b-ab845d3feb85:Active', 'master_uuid': u'8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b', 'version': '3', 'spm_id': 1, 'type': 'LOCALFS', 'master_ver': 1}, 'dominfo': {'2cee08e0-e675-480a-903c-61f5fe244841': {'status': 'Active', 'diskfree': '266550116352', 'isoprefix': u'/rhev/data-center/mnt/esther.joris2k.nl:_mnt_data_iso/2cee08e0-e675-480a-903c-61f5fe244841/images/11111111-1111-1111-1111-111111111111', 'alerts': [], 'disktotal': '938684186624', 'version': 0}, '8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b': {'status': 'Active', 'diskfree': '266549284864', 'isoprefix': '', 'alerts': [], 'disktotal': '938683396096', 'version': 3}, 'b6901ec1-7992-4ff8-a728-08bc47103f67': {'status': 'Active', 'diskfree': '379594899456', 'isoprefix': '', 'alerts': [], 'disktotal': '1476210552832', 'version': 3}, 'e1826a4b-eeb8-4ec3-bb6b-ab845d3feb85': {'status': 'Active', 'diskfree': '136929796096', 'isoprefix': '', 'alerts': [], 'disktotal': '147831037952', 'version': 3}}}
Thread-32532::DEBUG::2015-10-21 20:15:46,223::task::1191::Storage.TaskManager.Task::(prepare) Task=`21932d0f-0da3-4029-8a90-044060557189`::finished: {'info': {'name': 'No Description', 'isoprefix': u'/rhev/data-center/mnt/esther.joris2k.nl:_mnt_data_iso/2cee08e0-e675-480a-903c-61f5fe244841/images/11111111-1111-1111-1111-111111111111', 'pool_status': 'connected', 'lver': -1, 'domains': '2cee08e0-e675-480a-903c-61f5fe244841:Active,8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b:Active,b6901ec1-7992-4ff8-a728-08bc47103f67:Active,e1826a4b-eeb8-4ec3-bb6b-ab845d3feb85:Active', 'master_uuid': u'8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b', 'version': '3', 'spm_id': 1, 'type': 'LOCALFS', 'master_ver': 1}, 'dominfo': {'2cee08e0-e675-480a-903c-61f5fe244841': {'status': 'Active', 'diskfree': '266550116352', 'isoprefix': u'/rhev/data-center/mnt/esther.joris2k.nl:_mnt_data_iso/2cee08e0-e675-480a-903c-61f5fe244841/images/11111111-1111-1111-1111-111111111111', 'alerts': [], 'disktotal': '938684186624', 'version': 0}, '8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b': {'status': 'Active', 'diskfree': '266549284864', 'isoprefix': '', 'alerts': [], 'disktotal': '938683396096', 'version': 3}, 'b6901ec1-7992-4ff8-a728-08bc47103f67': {'status': 'Active', 'diskfree': '379594899456', 'isoprefix': '', 'alerts': [], 'disktotal': '1476210552832', 'version': 3}, 'e1826a4b-eeb8-4ec3-bb6b-ab845d3feb85': {'status': 'Active', 'diskfree': '136929796096', 'isoprefix': '', 'alerts': [], 'disktotal': '147831037952', 'version': 3}}}
Thread-32532::DEBUG::2015-10-21 20:15:46,224::task::595::Storage.TaskManager.Task::(_updateState) Task=`21932d0f-0da3-4029-8a90-044060557189`::moving from state preparing -> state finished
Thread-32532::DEBUG::2015-10-21 20:15:46,224::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.c3715f80-6435-45b6-94c2-a9a2869cd059': < ResourceRef 'Storage.c3715f80-6435-45b6-94c2-a9a2869cd059', isValid: 'True' obj: 'None'>}
Thread-32532::DEBUG::2015-10-21 20:15:46,224::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-32532::DEBUG::2015-10-21 20:15:46,224::resourceManager::616::Storage.ResourceManager::(releaseResource) Trying to release resource 'Storage.c3715f80-6435-45b6-94c2-a9a2869cd059'
Thread-32532::DEBUG::2015-10-21 20:15:46,224::resourceManager::635::Storage.ResourceManager::(releaseResource) Released resource 'Storage.c3715f80-6435-45b6-94c2-a9a2869cd059' (0 active users)
Thread-32532::DEBUG::2015-10-21 20:15:46,224::resourceManager::641::Storage.ResourceManager::(releaseResource) Resource 'Storage.c3715f80-6435-45b6-94c2-a9a2869cd059' is free, finding out if anyone is waiting for it.
Thread-32532::DEBUG::2015-10-21 20:15:46,224::resourceManager::649::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'Storage.c3715f80-6435-45b6-94c2-a9a2869cd059', Clearing records.
Thread-32532::DEBUG::2015-10-21 20:15:46,224::task::993::Storage.TaskManager.Task::(_decref) Task=`21932d0f-0da3-4029-8a90-044060557189`::ref 0 aborting False
Thread-32532::DEBUG::2015-10-21 20:15:46,224::__init__::514::jsonrpc.JsonRpcServer::(_serveRequest) Return 'StoragePool.getInfo' in bridge with {'info': {'name': 'No Description', 'isoprefix': u'/rhev/data-center/mnt/esther.joris2k.nl:_mnt_data_iso/2cee08e0-e675-480a-903c-61f5fe244841/images/11111111-1111-1111-1111-111111111111', 'pool_status': 'connected', 'lver': -1, 'domains': '2cee08e0-e675-480a-903c-61f5fe244841:Active,8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b:Active,b6901ec1-7992-4ff8-a728-08bc47103f67:Active,e1826a4b-eeb8-4ec3-bb6b-ab845d3feb85:Active', 'master_uuid': u'8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b', 'version': '3', 'spm_id': 1, 'type': 'LOCALFS', 'master_ver': 1}, 'dominfo': {'2cee08e0-e675-480a-903c-61f5fe244841': {'status': 'Active', 'diskfree': '266550116352', 'isoprefix': u'/rhev/data-center/mnt/esther.joris2k.nl:_mnt_data_iso/2cee08e0-e675-480a-903c-61f5fe244841/images/11111111-1111-1111-1111-111111111111', 'alerts': [], 'disktotal': '938684186624', 'version': 0}, '8fd14fae-9cd2-40f8-aa12-5b6a4f21c57b': {'status': 'Active', 'diskfree': '266549284864', 'isoprefix': '', 'alerts': [], 'disktotal': '938683396096', 'version': 3}, 'b6901ec1-7992-4ff8-a728-08bc47103f67': {'status': 'Active', 'diskfree': '379594899456', 'isoprefix': '', 'alerts': [], 'disktotal': '1476210552832', 'version': 3}, 'e1826a4b-eeb8-4ec3-bb6b-ab845d3feb85': {'status': 'Active', 'diskfree': '136929796096', 'isoprefix': '', 'alerts': [], 'disktotal': '147831037952', 'version': 3}}}
