Thread-4574::DEBUG::2015-02-25 20:10:13,701::task::1191::Storage.TaskManager.Task::(prepare) Task=`20e770ec-87d9-47b8-8969-9bc50f8b8c88`::finished: {'truesize': '2616532992', 'apparentsize': '64424509440'}
Thread-1753::DEBUG::2015-02-25 20:10:13,702::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-4574::DEBUG::2015-02-25 20:10:13,702::task::595::Storage.TaskManager.Task::(_updateState) Task=`20e770ec-87d9-47b8-8969-9bc50f8b8c88`::moving from state preparing -> state finished
Thread-1753::DEBUG::2015-02-25 20:10:13,703::task::993::Storage.TaskManager.Task::(_decref) Task=`8040385c-b701-4ddd-89c6-14e30c619999`::ref 0 aborting False
Thread-4574::DEBUG::2015-02-25 20:10:13,703::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-4574::DEBUG::2015-02-25 20:10:13,704::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-4574::DEBUG::2015-02-25 20:10:13,704::task::993::Storage.TaskManager.Task::(_decref) Task=`20e770ec-87d9-47b8-8969-9bc50f8b8c88`::ref 0 aborting False
Thread-590::DEBUG::2015-02-25 20:10:13,936::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-1753::DEBUG::2015-02-25 20:10:13,960::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-4574::DEBUG::2015-02-25 20:10:13,970::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-24::DEBUG::2015-02-25 20:10:15,394::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd if=/rhev/data-center/mnt/glusterSD/10.10.0.14:_ds01/e732a82f-bae9-4368-8b98-dedc1c3814de/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-24::DEBUG::2015-02-25 20:10:15,629::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n457 bytes (457 B) copied, 0.000905785 s, 505 kB/s\n'; <rc> = 0
Thread-606::DEBUG::2015-02-25 20:10:16,075::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-4437::DEBUG::2015-02-25 20:10:16,683::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-627::DEBUG::2015-02-25 20:10:16,684::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-5186::DEBUG::2015-02-25 20:10:16,687::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-659::DEBUG::2015-02-25 20:10:17,381::task::595::Storage.TaskManager.Task::(_updateState) Task=`f4fe70e2-09ec-4333-8f23-c513668b2d78`::moving from state init -> state preparing
Thread-659::INFO::2015-02-25 20:10:17,383::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='e732a82f-bae9-4368-8b98-dedc1c3814de', spUUID='00000002-0002-0002-0002-000000000145', imgUUID='343ec1cb-87d0-4965-9693-8d70b8303dee', volUUID='2873e00b-b02b-4bb4-a293-e7f237572d12', options=None)
Thread-659::INFO::2015-02-25 20:10:17,393::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '1586053120', 'apparentsize': '21474836480'}
Thread-659::DEBUG::2015-02-25 20:10:17,394::task::1191::Storage.TaskManager.Task::(prepare) Task=`f4fe70e2-09ec-4333-8f23-c513668b2d78`::finished: {'truesize': '1586053120', 'apparentsize': '21474836480'}
Thread-659::DEBUG::2015-02-25 20:10:17,395::task::595::Storage.TaskManager.Task::(_updateState) Task=`f4fe70e2-09ec-4333-8f23-c513668b2d78`::moving from state preparing -> state finished
Thread-659::DEBUG::2015-02-25 20:10:17,396::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-659::DEBUG::2015-02-25 20:10:17,396::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-659::DEBUG::2015-02-25 20:10:17,397::task::993::Storage.TaskManager.Task::(_decref) Task=`f4fe70e2-09ec-4333-8f23-c513668b2d78`::ref 0 aborting False
Thread-659::DEBUG::2015-02-25 20:10:17,529::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-379::DEBUG::2015-02-25 20:10:17,707::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-9518::ERROR::2015-02-25 20:10:17,941::task::866::Storage.TaskManager.Task::(_setError) Task=`8b8d0a5a-40e2-4ebf-a5d7-b3dbb383ff81`::Unexpected error
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/task.py", line 873, in _run
    return fn(*args, **kargs)
  File "/usr/share/vdsm/logUtils.py", line 45, in wrapper
    res = f(*args, **kwargs)
  File "/usr/share/vdsm/storage/hsm.py", line 3205, in prepareImage
    allVols = dom.getAllVolumes()
  File "/usr/share/vdsm/storage/fileSD.py", line 425, in getAllVolumes
    volMetaPaths = self.oop.glob.glob(volMetaPattern)
  File "/usr/share/vdsm/storage/outOfProcess.py", line 89, in glob
    return self._iop.glob(pattern)
  File "/usr/lib/python2.7/site-packages/ioprocess/__init__.py", line 500, in glob
    return self._sendCommand("glob", {"pattern": pattern}, self.timeout)
  File "/usr/lib/python2.7/site-packages/ioprocess/__init__.py", line 385, in _sendCommand
    raise Timeout(os.strerror(errno.ETIMEDOUT))
Timeout: Connection timed out
Thread-9518::DEBUG::2015-02-25 20:10:17,942::task::885::Storage.TaskManager.Task::(_run) Task=`8b8d0a5a-40e2-4ebf-a5d7-b3dbb383ff81`::Task._run: 8b8d0a5a-40e2-4ebf-a5d7-b3dbb383ff81 ('e732a82f-bae9-4368-8b98-dedc1c3814de', '00000002-0002-0002-0002-000000000145', '8ca66096-bd47-460d-9e09-2966e45b471b', '60c73bf0-d190-420b-917c-04aa00e52f10') {} failed - stopping task
Thread-9518::DEBUG::2015-02-25 20:10:17,942::task::1217::Storage.TaskManager.Task::(stop) Task=`8b8d0a5a-40e2-4ebf-a5d7-b3dbb383ff81`::stopping in state preparing (force False)
Thread-9518::DEBUG::2015-02-25 20:10:17,942::task::993::Storage.TaskManager.Task::(_decref) Task=`8b8d0a5a-40e2-4ebf-a5d7-b3dbb383ff81`::ref 1 aborting True
Thread-9518::INFO::2015-02-25 20:10:17,943::task::1171::Storage.TaskManager.Task::(prepare) Task=`8b8d0a5a-40e2-4ebf-a5d7-b3dbb383ff81`::aborting: Task is aborted: u'Connection timed out' - code 100
Thread-9518::DEBUG::2015-02-25 20:10:17,943::task::1176::Storage.TaskManager.Task::(prepare) Task=`8b8d0a5a-40e2-4ebf-a5d7-b3dbb383ff81`::Prepare: aborted: Connection timed out
Thread-9518::DEBUG::2015-02-25 20:10:17,943::task::993::Storage.TaskManager.Task::(_decref) Task=`8b8d0a5a-40e2-4ebf-a5d7-b3dbb383ff81`::ref 0 aborting True
Thread-9518::DEBUG::2015-02-25 20:10:17,943::task::928::Storage.TaskManager.Task::(_doAbort) Task=`8b8d0a5a-40e2-4ebf-a5d7-b3dbb383ff81`::Task._doAbort: force False
Thread-9518::DEBUG::2015-02-25 20:10:17,943::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-9518::DEBUG::2015-02-25 20:10:17,944::task::595::Storage.TaskManager.Task::(_updateState) Task=`8b8d0a5a-40e2-4ebf-a5d7-b3dbb383ff81`::moving from state preparing -> state aborting
Thread-9518::DEBUG::2015-02-25 20:10:17,944::task::550::Storage.TaskManager.Task::(__state_aborting) Task=`8b8d0a5a-40e2-4ebf-a5d7-b3dbb383ff81`::_aborting: recover policy none
Thread-9518::DEBUG::2015-02-25 20:10:17,944::task::595::Storage.TaskManager.Task::(_updateState) Task=`8b8d0a5a-40e2-4ebf-a5d7-b3dbb383ff81`::moving from state aborting -> state failed
Thread-9518::DEBUG::2015-02-25 20:10:17,944::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.e732a82f-bae9-4368-8b98-dedc1c3814de': < ResourceRef 'Storage.e732a82f-bae9-4368-8b98-dedc1c3814de', isValid: 'True' obj: 'None'>}
Thread-9518::DEBUG::2015-02-25 20:10:17,944::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-9518::DEBUG::2015-02-25 20:10:17,945::resourceManager::616::Storage.ResourceManager::(releaseResource) Trying to release resource 'Storage.e732a82f-bae9-4368-8b98-dedc1c3814de'
Thread-9518::DEBUG::2015-02-25 20:10:17,945::resourceManager::635::Storage.ResourceManager::(releaseResource) Released resource 'Storage.e732a82f-bae9-4368-8b98-dedc1c3814de' (0 active users)
Thread-9518::DEBUG::2015-02-25 20:10:17,945::resourceManager::641::Storage.ResourceManager::(releaseResource) Resource 'Storage.e732a82f-bae9-4368-8b98-dedc1c3814de' is free, finding out if anyone is waiting for it.
Thread-9518::DEBUG::2015-02-25 20:10:17,945::resourceManager::649::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'Storage.e732a82f-bae9-4368-8b98-dedc1c3814de', Clearing records.
Thread-9518::ERROR::2015-02-25 20:10:17,946::dispatcher::79::Storage.Dispatcher::(wrapper) Connection timed out
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/dispatcher.py", line 71, in wrapper
    result = ctask.prepare(func, *args, **kwargs)
  File "/usr/share/vdsm/storage/task.py", line 103, in wrapper
    return m(self, *a, **kw)
  File "/usr/share/vdsm/storage/task.py", line 1179, in prepare
    raise self.error
Timeout: Connection timed out
Thread-9518::DEBUG::2015-02-25 20:10:17,946::vm::2294::vm.Vm::(_startUnderlyingVm) vmId=`93536f77-d1d8-4bb9-a7b9-ba20da66579f`::_ongoingCreations released
Thread-9518::ERROR::2015-02-25 20:10:17,947::vm::2331::vm.Vm::(_startUnderlyingVm) vmId=`93536f77-d1d8-4bb9-a7b9-ba20da66579f`::The vm start process failed
Traceback (most recent call last):
  File "/usr/share/vdsm/virt/vm.py", line 2271, in _startUnderlyingVm
    self._run()
  File "/usr/share/vdsm/virt/vm.py", line 3266, in _run
    self.preparePaths(devices[DISK_DEVICES])
  File "/usr/share/vdsm/virt/vm.py", line 2353, in preparePaths
    drive['path'] = self.cif.prepareVolumePath(drive, self.id)
  File "/usr/share/vdsm/clientIF.py", line 277, in prepareVolumePath
    raise vm.VolumeError(drive)
VolumeError: Bad volume specification {'index': 0, 'iface': 'virtio', 'type': 'disk', 'format': 'raw', 'bootOrder': '1', 'address': {'slot': '0x07', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'volumeID': '60c73bf0-d190-420b-917c-04aa00e52f10', 'apparentsize': '1073741824', 'imageID': '8ca66096-bd47-460d-9e09-2966e45b471b', 'specParams': {}, 'readonly': 'false', 'domainID': 'e732a82f-bae9-4368-8b98-dedc1c3814de', 'reqsize': '0', 'deviceId': '8ca66096-bd47-460d-9e09-2966e45b471b', 'truesize': '1054048256', 'poolID': '00000002-0002-0002-0002-000000000145', 'device': 'disk', 'shared': 'false', 'propagateErrors': 'off', 'optional': 'false'}
Thread-9518::DEBUG::2015-02-25 20:10:17,948::vm::2786::vm.Vm::(setDownStatus) vmId=`93536f77-d1d8-4bb9-a7b9-ba20da66579f`::Changed state to Down: Bad volume specification {'index': 0, 'iface': 'virtio', 'type': 'disk', 'format': 'raw', 'bootOrder': '1', 'address': {'slot': '0x07', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'volumeID': '60c73bf0-d190-420b-917c-04aa00e52f10', 'apparentsize': '1073741824', 'imageID': '8ca66096-bd47-460d-9e09-2966e45b471b', 'specParams': {}, 'readonly': 'false', 'domainID': 'e732a82f-bae9-4368-8b98-dedc1c3814de', 'reqsize': '0', 'deviceId': '8ca66096-bd47-460d-9e09-2966e45b471b', 'truesize': '1054048256', 'poolID': '00000002-0002-0002-0002-000000000145', 'device': 'disk', 'shared': 'false', 'propagateErrors': 'off', 'optional': 'false'} (code=1)
Thread-1789::DEBUG::2015-02-25 20:10:18,073::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-2891::DEBUG::2015-02-25 20:10:18,336::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-1472::DEBUG::2015-02-25 20:10:18,666::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-1219::DEBUG::2015-02-25 20:10:18,667::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-929::DEBUG::2015-02-25 20:10:18,708::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-66::DEBUG::2015-02-25 20:10:18,825::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-1399::DEBUG::2015-02-25 20:10:18,948::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-9472::DEBUG::2015-02-25 20:10:19,097::BindingXMLRPC::1133::vds::(wrapper) client [43.252.177.2]::call vmGetStats with ('93536f77-d1d8-4bb9-a7b9-ba20da66579f',) {}
Thread-9472::DEBUG::2015-02-25 20:10:19,097::BindingXMLRPC::1140::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Down', 'exitMessage': "Bad volume specification {'index': 0, 'iface': 'virtio', 'type': 'disk', 'format': 'raw', 'bootOrder': '1', 'address': {'slot': '0x07', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'volumeID': '60c73bf0-d190-420b-917c-04aa00e52f10', 'apparentsize': '1073741824', 'imageID': '8ca66096-bd47-460d-9e09-2966e45b471b', 'specParams': {}, 'readonly': 'false', 'domainID': 'e732a82f-bae9-4368-8b98-dedc1c3814de', 'reqsize': '0', 'deviceId': '8ca66096-bd47-460d-9e09-2966e45b471b', 'truesize': '1054048256', 'poolID': '00000002-0002-0002-0002-000000000145', 'device': 'disk', 'shared': 'false', 'propagateErrors': 'off', 'optional': 'false'}", 'vmId': '93536f77-d1d8-4bb9-a7b9-ba20da66579f', 'exitReason': 1, 'timeOffset': '28800', 'exitCode': 1}]}
Thread-9472::DEBUG::2015-02-25 20:10:19,120::BindingXMLRPC::1133::vds::(wrapper) client [43.252.177.2]::call vmDestroy with ('93536f77-d1d8-4bb9-a7b9-ba20da66579f',) {}
Thread-9472::INFO::2015-02-25 20:10:19,121::API::332::vds::(destroy) vmContainerLock acquired by vm 93536f77-d1d8-4bb9-a7b9-ba20da66579f
Thread-9472::DEBUG::2015-02-25 20:10:19,121::vm::5026::vm.Vm::(destroy) vmId=`93536f77-d1d8-4bb9-a7b9-ba20da66579f`::destroy Called
Thread-9472::INFO::2015-02-25 20:10:19,121::vm::4952::vm.Vm::(releaseVm) vmId=`93536f77-d1d8-4bb9-a7b9-ba20da66579f`::Release VM resources
Thread-9472::WARNING::2015-02-25 20:10:19,122::vm::1953::vm.Vm::(_set_lastStatus) vmId=`93536f77-d1d8-4bb9-a7b9-ba20da66579f`::trying to set state to Powering down when already Down
Thread-9472::WARNING::2015-02-25 20:10:19,122::utils::129::root::(rmFile) File: /var/lib/libvirt/qemu/channels/93536f77-d1d8-4bb9-a7b9-ba20da66579f.com.redhat.rhevm.vdsm already removed
Thread-9472::WARNING::2015-02-25 20:10:19,122::utils::129::root::(rmFile) File: /var/lib/libvirt/qemu/channels/93536f77-d1d8-4bb9-a7b9-ba20da66579f.org.qemu.guest_agent.0 already removed
Thread-9472::DEBUG::2015-02-25 20:10:19,123::task::595::Storage.TaskManager.Task::(_updateState) Task=`529ec229-3447-4938-a0e8-9eaa873c4606`::moving from state init -> state preparing
Thread-9472::INFO::2015-02-25 20:10:19,123::logUtils::44::dispatcher::(wrapper) Run and protect: inappropriateDevices(thiefId='93536f77-d1d8-4bb9-a7b9-ba20da66579f')
Thread-9472::INFO::2015-02-25 20:10:19,125::logUtils::47::dispatcher::(wrapper) Run and protect: inappropriateDevices, Return response: None
Thread-9472::DEBUG::2015-02-25 20:10:19,125::task::1191::Storage.TaskManager.Task::(prepare) Task=`529ec229-3447-4938-a0e8-9eaa873c4606`::finished: None
Thread-9472::DEBUG::2015-02-25 20:10:19,126::task::595::Storage.TaskManager.Task::(_updateState) Task=`529ec229-3447-4938-a0e8-9eaa873c4606`::moving from state preparing -> state finished
Thread-9472::DEBUG::2015-02-25 20:10:19,126::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-9472::DEBUG::2015-02-25 20:10:19,126::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-9472::DEBUG::2015-02-25 20:10:19,126::task::993::Storage.TaskManager.Task::(_decref) Task=`529ec229-3447-4938-a0e8-9eaa873c4606`::ref 0 aborting False
Thread-9472::DEBUG::2015-02-25 20:10:19,127::vm::5020::vm.Vm::(deleteVm) vmId=`93536f77-d1d8-4bb9-a7b9-ba20da66579f`::Total desktops after destroy of 93536f77-d1d8-4bb9-a7b9-ba20da66579f is 77
Thread-9472::DEBUG::2015-02-25 20:10:19,128::BindingXMLRPC::1140::vds::(wrapper) return vmDestroy with {'status': {'message': 'Machine destroyed', 'code': 0}}
Thread-630::DEBUG::2015-02-25 20:10:19,784::task::595::Storage.TaskManager.Task::(_updateState) Task=`589aab35-0d4d-4ad5-9ef0-99dbc498a523`::moving from state init -> state preparing
Thread-4595::DEBUG::2015-02-25 20:10:19,788::task::595::Storage.TaskManager.Task::(_updateState) Task=`c10fa011-749a-459e-8430-d609c8715878`::moving from state init -> state preparing
Thread-630::INFO::2015-02-25 20:10:19,870::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='e732a82f-bae9-4368-8b98-dedc1c3814de', spUUID='00000002-0002-0002-0002-000000000145', imgUUID='adcce117-7473-4571-b7d9-c8bef7faa6d2', volUUID='e2edbf15-ce1f-41e6-b1e6-3b3208114681', options=None)
Thread-4595::INFO::2015-02-25 20:10:19,884::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='e732a82f-bae9-4368-8b98-dedc1c3814de', spUUID='00000002-0002-0002-0002-000000000145', imgUUID='0fa16768-ed68-4aaa-9e88-defb0ae4341f', volUUID='a2978843-fce9-421f-b196-77861659d839', options=None)
Thread-185::DEBUG::2015-02-25 20:10:20,081::task::595::Storage.TaskManager.Task::(_updateState) Task=`1431d327-8e09-409c-bc42-ac17d6f3579e`::moving from state init -> state preparing
Thread-1713::DEBUG::2015-02-25 20:10:20,099::task::595::Storage.TaskManager.Task::(_updateState) Task=`15485caf-3df0-4775-9ae0-32cd3262a0f3`::moving from state init -> state preparing
Thread-1084::DEBUG::2015-02-25 20:10:20,099::task::595::Storage.TaskManager.Task::(_updateState) Task=`ba80d4be-88ec-4f60-97ce-8eff5c4a43d5`::moving from state init -> state preparing
Thread-727::DEBUG::2015-02-25 20:10:20,088::task::595::Storage.TaskManager.Task::(_updateState) Task=`5861d8ff-219a-4c6c-bdab-a0e84bd582b2`::moving from state init -> state preparing
Thread-2706::DEBUG::2015-02-25 20:10:20,102::task::595::Storage.TaskManager.Task::(_updateState) Task=`85342ba4-8ba5-4769-a905-a3b1827c4e1a`::moving from state init -> state preparing
Thread-1521::DEBUG::2015-02-25 20:10:20,094::task::595::Storage.TaskManager.Task::(_updateState) Task=`6888e062-5b42-4807-b188-d71924f75c86`::moving from state init -> state preparing
Thread-2456::DEBUG::2015-02-25 20:10:20,095::task::595::Storage.TaskManager.Task::(_updateState) Task=`667a9b99-2222-4b0b-ba75-31265d53d74c`::moving from state init -> state preparing
Thread-3002::DEBUG::2015-02-25 20:10:20,102::task::595::Storage.TaskManager.Task::(_updateState) Task=`1550decf-d95f-4f5e-932c-73b519365837`::moving from state init -> state preparing
Thread-2016::DEBUG::2015-02-25 20:10:20,106::task::595::Storage.TaskManager.Task::(_updateState) Task=`5fb96285-1f25-4bb4-8ccf-5dfe7b8815e8`::moving from state init -> state preparing
Thread-576::DEBUG::2015-02-25 20:10:20,140::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-1894::DEBUG::2015-02-25 20:10:20,142::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-185::INFO::2015-02-25 20:10:20,174::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='e732a82f-bae9-4368-8b98-dedc1c3814de', spUUID='00000002-0002-0002-0002-000000000145', imgUUID='03a729fb-90d5-4e7b-bc69-ba2fc77759de', volUUID='6a8622cd-3404-43ce-8daa-e74910c58e95', options=None)
Thread-1713::INFO::2015-02-25 20:10:20,196::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='e732a82f-bae9-4368-8b98-dedc1c3814de', spUUID='00000002-0002-0002-0002-000000000145', imgUUID='30949685-e0ec-4a70-9a26-994cd61dd0e1', volUUID='b092db9b-1100-44e2-b373-4c98bb0fa839', options=None)
Thread-1084::INFO::2015-02-25 20:10:20,218::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='e732a82f-bae9-4368-8b98-dedc1c3814de', spUUID='00000002-0002-0002-0002-000000000145', imgUUID='0e0a0a2b-830e-4703-93c0-263e2bc233bc', volUUID='2503b59b-3959-431c-a58d-4723261932a9', options=None)
Thread-630::INFO::2015-02-25 20:10:20,222::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '1445519360', 'apparentsize': '64424509440'}
Thread-727::INFO::2015-02-25 20:10:20,242::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='e732a82f-bae9-4368-8b98-dedc1c3814de', spUUID='00000002-0002-0002-0002-000000000145', imgUUID='5df902f9-1d61-445e-ab83-00523ecbbe72', volUUID='897095a5-ff22-41c9-a394-59122d438a19', options=None)
Thread-2706::INFO::2015-02-25 20:10:20,257::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='e732a82f-bae9-4368-8b98-dedc1c3814de', spUUID='00000002-0002-0002-0002-000000000145', imgUUID='3d338434-ff53-4b51-ab66-7d72dc691cda', volUUID='08954036-38d7-4a52-a923-881adc08dbe6', options=None)
Thread-1521::INFO::2015-02-25 20:10:20,285::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='e732a82f-bae9-4368-8b98-dedc1c3814de', spUUID='00000002-0002-0002-0002-000000000145', imgUUID='058490dd-ffdb-42fb-8fae-dee1f160198f', volUUID='d2099de0-0978-4c89-8dc5-af568ab50db5', options=None)
Thread-4595::INFO::2015-02-25 20:10:20,287::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '2540642304', 'apparentsize': '64424509440'}
Thread-2456::INFO::2015-02-25 20:10:20,295::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='e732a82f-bae9-4368-8b98-dedc1c3814de', spUUID='00000002-0002-0002-0002-000000000145', imgUUID='ee2aab3d-37be-44cf-b1e3-420ef96ca719', volUUID='47a1e58f-c5f0-4818-92ad-2b93d869d67e', options=None)
Thread-3002::INFO::2015-02-25 20:10:20,316::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='e732a82f-bae9-4368-8b98-dedc1c3814de', spUUID='00000002-0002-0002-0002-000000000145', imgUUID='699422bd-0120-4da1-b6cc-b7e1349af0a9', volUUID='ea51325e-83cf-4abe-be8d-104c47ba9503', options=None)
Thread-2016::INFO::2015-02-25 20:10:20,332::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='e732a82f-bae9-4368-8b98-dedc1c3814de', spUUID='00000002-0002-0002-0002-000000000145', imgUUID='fc8337a2-12c3-48b7-b2fc-aedb275aa60a', volUUID='a6cc4716-3989-451c-a1d3-1e84ad1f4ef3', options=None)
Thread-630::DEBUG::2015-02-25 20:10:20,426::task::1191::Storage.TaskManager.Task::(prepare) Task=`589aab35-0d4d-4ad5-9ef0-99dbc498a523`::finished: {'truesize': '1445519360', 'apparentsize': '64424509440'}
Thread-1661::DEBUG::2015-02-25 20:10:20,435::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-4595::DEBUG::2015-02-25 20:10:20,454::task::1191::Storage.TaskManager.Task::(prepare) Task=`c10fa011-749a-459e-8430-d609c8715878`::finished: {'truesize': '2540642304', 'apparentsize': '64424509440'}
Thread-630::DEBUG::2015-02-25 20:10:20,473::task::595::Storage.TaskManager.Task::(_updateState) Task=`589aab35-0d4d-4ad5-9ef0-99dbc498a523`::moving from state preparing -> state finished
Thread-4595::DEBUG::2015-02-25 20:10:20,487::task::595::Storage.TaskManager.Task::(_updateState) Task=`c10fa011-749a-459e-8430-d609c8715878`::moving from state preparing -> state finished
Thread-630::DEBUG::2015-02-25 20:10:20,492::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-4595::DEBUG::2015-02-25 20:10:20,504::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-630::DEBUG::2015-02-25 20:10:20,510::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-4595::DEBUG::2015-02-25 20:10:20,521::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-630::DEBUG::2015-02-25 20:10:20,529::task::993::Storage.TaskManager.Task::(_decref) Task=`589aab35-0d4d-4ad5-9ef0-99dbc498a523`::ref 0 aborting False
Thread-4595::DEBUG::2015-02-25 20:10:20,538::task::993::Storage.TaskManager.Task::(_decref) Task=`c10fa011-749a-459e-8430-d609c8715878`::ref 0 aborting False
Thread-185::INFO::2015-02-25 20:10:20,562::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '1060478976', 'apparentsize': '21474836480'}
Thread-185::DEBUG::2015-02-25 20:10:20,571::task::1191::Storage.TaskManager.Task::(prepare) Task=`1431d327-8e09-409c-bc42-ac17d6f3579e`::finished: {'truesize': '1060478976', 'apparentsize': '21474836480'}
Thread-185::DEBUG::2015-02-25 20:10:20,579::task::595::Storage.TaskManager.Task::(_updateState) Task=`1431d327-8e09-409c-bc42-ac17d6f3579e`::moving from state preparing -> state finished
Thread-185::DEBUG::2015-02-25 20:10:20,587::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-185::DEBUG::2015-02-25 20:10:20,594::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-1713::INFO::2015-02-25 20:10:20,598::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '1628090368', 'apparentsize': '42949672960'}
Thread-185::DEBUG::2015-02-25 20:10:20,603::task::993::Storage.TaskManager.Task::(_decref) Task=`1431d327-8e09-409c-bc42-ac17d6f3579e`::ref 0 aborting False
Thread-1084::INFO::2015-02-25 20:10:20,608::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '1940242432', 'apparentsize': '21474836480'}
Thread-1713::DEBUG::2015-02-25 20:10:20,608::task::1191::Storage.TaskManager.Task::(prepare) Task=`15485caf-3df0-4775-9ae0-32cd3262a0f3`::finished: {'truesize': '1628090368', 'apparentsize': '42949672960'}
Thread-1713::DEBUG::2015-02-25 20:10:20,621::task::595::Storage.TaskManager.Task::(_updateState) Task=`15485caf-3df0-4775-9ae0-32cd3262a0f3`::moving from state preparing -> state finished
Thread-1084::DEBUG::2015-02-25 20:10:20,621::task::1191::Storage.TaskManager.Task::(prepare) Task=`ba80d4be-88ec-4f60-97ce-8eff5c4a43d5`::finished: {'truesize': '1940242432', 'apparentsize': '21474836480'}
Thread-727::INFO::2015-02-25 20:10:20,624::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '1782235136', 'apparentsize': '21474836480'}
Thread-1713::DEBUG::2015-02-25 20:10:20,630::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-1084::DEBUG::2015-02-25 20:10:20,634::task::595::Storage.TaskManager.Task::(_updateState) Task=`ba80d4be-88ec-4f60-97ce-8eff5c4a43d5`::moving from state preparing -> state finished
Thread-2706::INFO::2015-02-25 20:10:20,637::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '1787797504', 'apparentsize': '21474836480'}
Thread-1713::DEBUG::2015-02-25 20:10:20,640::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-727::DEBUG::2015-02-25 20:10:20,642::task::1191::Storage.TaskManager.Task::(prepare) Task=`5861d8ff-219a-4c6c-bdab-a0e84bd582b2`::finished: {'truesize': '1782235136', 'apparentsize': '21474836480'}
Thread-1084::DEBUG::2015-02-25 20:10:20,644::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-1521::INFO::2015-02-25 20:10:20,653::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '5755490304', 'apparentsize': '21474836480'}
Thread-2706::DEBUG::2015-02-25 20:10:20,655::task::1191::Storage.TaskManager.Task::(prepare) Task=`85342ba4-8ba5-4769-a905-a3b1827c4e1a`::finished: {'truesize': '1787797504', 'apparentsize': '21474836480'}
Thread-1713::DEBUG::2015-02-25 20:10:20,658::task::993::Storage.TaskManager.Task::(_decref) Task=`15485caf-3df0-4775-9ae0-32cd3262a0f3`::ref 0 aborting False
Thread-727::DEBUG::2015-02-25 20:10:20,660::task::595::Storage.TaskManager.Task::(_updateState) Task=`5861d8ff-219a-4c6c-bdab-a0e84bd582b2`::moving from state preparing -> state finished
Thread-1084::DEBUG::2015-02-25 20:10:20,663::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-2456::INFO::2015-02-25 20:10:20,669::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '1868374016', 'apparentsize': '21474836480'}
Thread-2706::DEBUG::2015-02-25 20:10:20,673::task::595::Storage.TaskManager.Task::(_updateState) Task=`85342ba4-8ba5-4769-a905-a3b1827c4e1a`::moving from state preparing -> state finished
Thread-1521::DEBUG::2015-02-25 20:10:20,674::task::1191::Storage.TaskManager.Task::(prepare) Task=`6888e062-5b42-4807-b188-d71924f75c86`::finished: {'truesize': '5755490304', 'apparentsize': '21474836480'}
Thread-727::DEBUG::2015-02-25 20:10:20,682::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-3002::INFO::2015-02-25 20:10:20,687::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '1431318528', 'apparentsize': '64424509440'}
Thread-1084::DEBUG::2015-02-25 20:10:20,693::task::993::Storage.TaskManager.Task::(_decref) Task=`ba80d4be-88ec-4f60-97ce-8eff5c4a43d5`::ref 0 aborting False
Thread-2706::DEBUG::2015-02-25 20:10:20,700::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-2456::DEBUG::2015-02-25 20:10:20,702::task::1191::Storage.TaskManager.Task::(prepare) Task=`667a9b99-2222-4b0b-ba75-31265d53d74c`::finished: {'truesize': '1868374016', 'apparentsize': '21474836480'}
Thread-1521::DEBUG::2015-02-25 20:10:20,706::task::595::Storage.TaskManager.Task::(_updateState) Task=`6888e062-5b42-4807-b188-d71924f75c86`::moving from state preparing -> state finished
Thread-2016::INFO::2015-02-25 20:10:20,709::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '3833016320', 'apparentsize': '21474836480'}
Thread-727::DEBUG::2015-02-25 20:10:20,709::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-3002::DEBUG::2015-02-25 20:10:20,716::task::1191::Storage.TaskManager.Task::(prepare) Task=`1550decf-d95f-4f5e-932c-73b519365837`::finished: {'truesize': '1431318528', 'apparentsize': '64424509440'}
Thread-2706::DEBUG::2015-02-25 20:10:20,718::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-2456::DEBUG::2015-02-25 20:10:20,721::task::595::Storage.TaskManager.Task::(_updateState) Task=`667a9b99-2222-4b0b-ba75-31265d53d74c`::moving from state preparing -> state finished
Thread-1521::DEBUG::2015-02-25 20:10:20,723::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-2016::DEBUG::2015-02-25 20:10:20,731::task::1191::Storage.TaskManager.Task::(prepare) Task=`5fb96285-1f25-4bb4-8ccf-5dfe7b8815e8`::finished: {'truesize': '3833016320', 'apparentsize': '21474836480'}
Thread-2456::DEBUG::2015-02-25 20:10:20,742::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-727::DEBUG::2015-02-25 20:10:20,734::task::993::Storage.TaskManager.Task::(_decref) Task=`5861d8ff-219a-4c6c-bdab-a0e84bd582b2`::ref 0 aborting False
Thread-3002::DEBUG::2015-02-25 20:10:20,734::task::595::Storage.TaskManager.Task::(_updateState) Task=`1550decf-d95f-4f5e-932c-73b519365837`::moving from state preparing -> state finished
Thread-2706::DEBUG::2015-02-25 20:10:20,741::task::993::Storage.TaskManager.Task::(_decref) Task=`85342ba4-8ba5-4769-a905-a3b1827c4e1a`::ref 0 aborting False
Thread-630::DEBUG::2015-02-25 20:10:20,733::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-4595::DEBUG::2015-02-25 20:10:20,745::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-1521::DEBUG::2015-02-25 20:10:20,745::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-386::DEBUG::2015-02-25 20:10:20,747::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-2016::DEBUG::2015-02-25 20:10:20,748::task::595::Storage.TaskManager.Task::(_updateState) Task=`5fb96285-1f25-4bb4-8ccf-5dfe7b8815e8`::moving from state preparing -> state finished
Thread-1471::DEBUG::2015-02-25 20:10:20,751::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-2456::DEBUG::2015-02-25 20:10:20,752::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-55::DEBUG::2015-02-25 20:10:20,753::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-3002::DEBUG::2015-02-25 20:10:20,758::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-1332::DEBUG::2015-02-25 20:10:20,760::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-1521::DEBUG::2015-02-25 20:10:20,771::task::993::Storage.TaskManager.Task::(_decref) Task=`6888e062-5b42-4807-b188-d71924f75c86`::ref 0 aborting False
Thread-2016::DEBUG::2015-02-25 20:10:20,773::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-481::DEBUG::2015-02-25 20:10:20,781::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-2456::DEBUG::2015-02-25 20:10:20,782::task::993::Storage.TaskManager.Task::(_decref) Task=`667a9b99-2222-4b0b-ba75-31265d53d74c`::ref 0 aborting False
Thread-3002::DEBUG::2015-02-25 20:10:20,786::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-2016::DEBUG::2015-02-25 20:10:20,794::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-1843::DEBUG::2015-02-25 20:10:20,796::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-3002::DEBUG::2015-02-25 20:10:20,803::task::993::Storage.TaskManager.Task::(_decref) Task=`1550decf-d95f-4f5e-932c-73b519365837`::ref 0 aborting False
Thread-2016::DEBUG::2015-02-25 20:10:20,806::task::993::Storage.TaskManager.Task::(_decref) Task=`5fb96285-1f25-4bb4-8ccf-5dfe7b8815e8`::ref 0 aborting False
Thread-505::DEBUG::2015-02-25 20:10:20,814::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-185::DEBUG::2015-02-25 20:10:20,835::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-1754::DEBUG::2015-02-25 20:10:20,937::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-422::DEBUG::2015-02-25 20:10:20,944::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-1713::DEBUG::2015-02-25 20:10:20,959::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-1084::DEBUG::2015-02-25 20:10:20,991::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-727::DEBUG::2015-02-25 20:10:21,008::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-2706::DEBUG::2015-02-25 20:10:21,017::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-2456::DEBUG::2015-02-25 20:10:21,027::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-1521::DEBUG::2015-02-25 20:10:21,028::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-3002::DEBUG::2015-02-25 20:10:21,042::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-2016::DEBUG::2015-02-25 20:10:21,050::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-25::DEBUG::2015-02-25 20:10:21,052::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd if=/rhev/data-center/mnt/117.18.79.72:_36Cloud__OStemplates/05be2753-83ed-4e6e-b236-4b342939a5fb/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-25::DEBUG::2015-02-25 20:10:21,306::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n345 bytes (345 B) copied, 0.00074813 s, 461 kB/s\n'; <rc> = 0
Thread-91::DEBUG::2015-02-25 20:10:22,073::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-540::DEBUG::2015-02-25 20:10:22,091::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-3312::DEBUG::2015-02-25 20:10:22,099::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-9472::DEBUG::2015-02-25 20:10:22,353::task::595::Storage.TaskManager.Task::(_updateState) Task=`8922ca25-ef19-420f-b0e5-d4f1d7aa3303`::moving from state init -> state preparing
Thread-9472::INFO::2015-02-25 20:10:22,353::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-9472::INFO::2015-02-25 20:10:22,354::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'e732a82f-bae9-4368-8b98-dedc1c3814de': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000905785', 'lastCheck': '6.7', 'valid': True}, '05be2753-83ed-4e6e-b236-4b342939a5fb': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.00074813', 'lastCheck': '1.0', 'valid': True}}
Thread-9472::DEBUG::2015-02-25 20:10:22,354::task::1191::Storage.TaskManager.Task::(prepare) Task=`8922ca25-ef19-420f-b0e5-d4f1d7aa3303`::finished: {'e732a82f-bae9-4368-8b98-dedc1c3814de': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000905785', 'lastCheck': '6.7', 'valid': True}, '05be2753-83ed-4e6e-b236-4b342939a5fb': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.00074813', 'lastCheck': '1.0', 'valid': True}}
Thread-9472::DEBUG::2015-02-25 20:10:22,354::task::595::Storage.TaskManager.Task::(_updateState) Task=`8922ca25-ef19-420f-b0e5-d4f1d7aa3303`::moving from state preparing -> state finished
Thread-9472::DEBUG::2015-02-25 20:10:22,355::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-9472::DEBUG::2015-02-25 20:10:22,355::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-9472::DEBUG::2015-02-25 20:10:22,355::task::993::Storage.TaskManager.Task::(_decref) Task=`8922ca25-ef19-420f-b0e5-d4f1d7aa3303`::ref 0 aborting False
Thread-2687::DEBUG::2015-02-25 20:10:22,831::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-02-25 20:10:22,835::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-1322::DEBUG::2015-02-25 20:10:23,335::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-467::DEBUG::2015-02-25 20:10:23,371::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-2517::DEBUG::2015-02-25 20:10:23,412::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-2541::DEBUG::2015-02-25 20:10:23,461::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-2760::DEBUG::2015-02-25 20:10:23,466::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-1259::DEBUG::2015-02-25 20:10:24,402::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-180::DEBUG::2015-02-25 20:10:24,682::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-1187::DEBUG::2015-02-25 20:10:24,746::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-57::DEBUG::2015-02-25 20:10:24,770::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-4731::DEBUG::2015-02-25 20:10:24,805::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-1059::DEBUG::2015-02-25 20:10:24,805::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-395::DEBUG::2015-02-25 20:10:24,929::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-138::DEBUG::2015-02-25 20:10:24,932::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-1417::DEBUG::2015-02-25 20:10:24,960::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-4645::DEBUG::2015-02-25 20:10:24,963::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-238::DEBUG::2015-02-25 20:10:25,213::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-1604::DEBUG::2015-02-25 20:10:25,321::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-1963::DEBUG::2015-02-25 20:10:25,397::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-1438::DEBUG::2015-02-25 20:10:25,417::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-199::DEBUG::2015-02-25 20:10:25,420::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-1576::DEBUG::2015-02-25 20:10:25,754::task::595::Storage.TaskManager.Task::(_updateState) Task=`bb912197-7700-4cbf-8433-183742750077`::moving from state init -> state preparing
Thread-2146::DEBUG::2015-02-25 20:10:25,759::task::595::Storage.TaskManager.Task::(_updateState) Task=`a7c906a1-37b7-4af7-af22-d3e3f44df5dc`::moving from state init -> state preparing
Thread-126::DEBUG::2015-02-25 20:10:25,761::task::595::Storage.TaskManager.Task::(_updateState) Task=`c0b42128-397a-44fb-be26-840d17e64acf`::moving from state init -> state preparing
Thread-24::DEBUG::2015-02-25 20:10:25,773::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd if=/rhev/data-center/mnt/glusterSD/10.10.0.14:_ds01/e732a82f-bae9-4368-8b98-dedc1c3814de/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-1576::INFO::2015-02-25 20:10:25,787::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='e732a82f-bae9-4368-8b98-dedc1c3814de', spUUID='00000002-0002-0002-0002-000000000145', imgUUID='0e3c961c-186f-4c5d-8fd2-8c7b10f11965', volUUID='492a8cc8-ae42-4e9a-9dd8-415fb881dcb8', options=None)
Thread-2146::INFO::2015-02-25 20:10:25,792::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='e732a82f-bae9-4368-8b98-dedc1c3814de', spUUID='00000002-0002-0002-0002-000000000145', imgUUID='77de8f34-9f4f-4166-ba39-28c7b8d95fe5', volUUID='4fa0b306-7da1-425a-81eb-ffc4e6e7e61a', options=None)
Thread-126::INFO::2015-02-25 20:10:25,796::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='e732a82f-bae9-4368-8b98-dedc1c3814de', spUUID='00000002-0002-0002-0002-000000000145', imgUUID='8269ef3a-f0bb-430b-bc44-462ce3d7eb37', volUUID='9427c5a5-951e-41e4-b537-b151d633e53a', options=None)
Thread-24::DEBUG::2015-02-25 20:10:26,066::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n457 bytes (457 B) copied, 0.000578947 s, 789 kB/s\n'; <rc> = 0
Thread-3013::DEBUG::2015-02-25 20:10:26,100::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-1576::INFO::2015-02-25 20:10:26,116::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '2751123456', 'apparentsize': '21474836480'}
Thread-2146::INFO::2015-02-25 20:10:26,128::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '1866563584', 'apparentsize': '21474836480'}
Thread-1576::DEBUG::2015-02-25 20:10:26,129::task::1191::Storage.TaskManager.Task::(prepare) Task=`bb912197-7700-4cbf-8433-183742750077`::finished: {'truesize': '2751123456', 'apparentsize': '21474836480'}
Thread-192::DEBUG::2015-02-25 20:10:26,137::task::595::Storage.TaskManager.Task::(_updateState) Task=`7fc2510a-4bed-4efe-befb-8bd989b2c257`::moving from state init -> state preparing
Thread-126::INFO::2015-02-25 20:10:26,139::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '1309061120', 'apparentsize': '21474836480'}
Thread-733::DEBUG::2015-02-25 20:10:26,139::task::595::Storage.TaskManager.Task::(_updateState) Task=`e849675c-c538-4f95-969a-ff9170b794ca`::moving from state init -> state preparing
Thread-1576::DEBUG::2015-02-25 20:10:26,141::task::595::Storage.TaskManager.Task::(_updateState) Task=`bb912197-7700-4cbf-8433-183742750077`::moving from state preparing -> state finished
Thread-2146::DEBUG::2015-02-25 20:10:26,141::task::1191::Storage.TaskManager.Task::(prepare) Task=`a7c906a1-37b7-4af7-af22-d3e3f44df5dc`::finished: {'truesize': '1866563584', 'apparentsize': '21474836480'}
Thread-192::INFO::2015-02-25 20:10:26,150::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='e732a82f-bae9-4368-8b98-dedc1c3814de', spUUID='00000002-0002-0002-0002-000000000145', imgUUID='abd5ce70-1083-4126-8582-517e4dcae9ee', volUUID='90b8bb3f-64bf-4419-81ec-f1733e13e6c9', options=None)
Thread-126::DEBUG::2015-02-25 20:10:26,154::task::1191::Storage.TaskManager.Task::(prepare) Task=`c0b42128-397a-44fb-be26-840d17e64acf`::finished: {'truesize': '1309061120', 'apparentsize': '21474836480'}
Thread-1576::DEBUG::2015-02-25 20:10:26,156::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-733::INFO::2015-02-25 20:10:26,157::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='e732a82f-bae9-4368-8b98-dedc1c3814de', spUUID='00000002-0002-0002-0002-000000000145', imgUUID='5db1fcf5-3c12-4567-996a-afa755026e8b', volUUID='2eb87b6f-8e27-4cbc-9bf3-4738a481f70c', options=None)
Thread-2146::DEBUG::2015-02-25 20:10:26,160::task::595::Storage.TaskManager.Task::(_updateState) Task=`a7c906a1-37b7-4af7-af22-d3e3f44df5dc`::moving from state preparing -> state finished
Thread-126::DEBUG::2015-02-25 20:10:26,167::task::595::Storage.TaskManager.Task::(_updateState) Task=`c0b42128-397a-44fb-be26-840d17e64acf`::moving from state preparing -> state finished
Thread-1576::DEBUG::2015-02-25 20:10:26,169::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-2146::DEBUG::2015-02-25 20:10:26,177::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-126::DEBUG::2015-02-25 20:10:26,181::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-1576::DEBUG::2015-02-25 20:10:26,185::task::993::Storage.TaskManager.Task::(_decref) Task=`bb912197-7700-4cbf-8433-183742750077`::ref 0 aborting False
Thread-2146::DEBUG::2015-02-25 20:10:26,185::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-126::DEBUG::2015-02-25 20:10:26,189::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-2146::DEBUG::2015-02-25 20:10:26,200::task::993::Storage.TaskManager.Task::(_decref) Task=`a7c906a1-37b7-4af7-af22-d3e3f44df5dc`::ref 0 aborting False
Thread-126::DEBUG::2015-02-25 20:10:26,203::task::993::Storage.TaskManager.Task::(_decref) Task=`c0b42128-397a-44fb-be26-840d17e64acf`::ref 0 aborting False
Thread-192::INFO::2015-02-25 20:10:26,223::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '1061470208', 'apparentsize': '21474836480'}
Thread-192::DEBUG::2015-02-25 20:10:26,233::task::1191::Storage.TaskManager.Task::(prepare) Task=`7fc2510a-4bed-4efe-befb-8bd989b2c257`::finished: {'truesize': '1061470208', 'apparentsize': '21474836480'}
Thread-733::INFO::2015-02-25 20:10:26,233::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '3779055616', 'apparentsize': '42949672960'}
Thread-192::DEBUG::2015-02-25 20:10:26,241::task::595::Storage.TaskManager.Task::(_updateState) Task=`7fc2510a-4bed-4efe-befb-8bd989b2c257`::moving from state preparing -> state finished
Thread-733::DEBUG::2015-02-25 20:10:26,245::task::1191::Storage.TaskManager.Task::(prepare) Task=`e849675c-c538-4f95-969a-ff9170b794ca`::finished: {'truesize': '3779055616', 'apparentsize': '42949672960'}
Thread-192::DEBUG::2015-02-25 20:10:26,249::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-733::DEBUG::2015-02-25 20:10:26,254::task::595::Storage.TaskManager.Task::(_updateState) Task=`e849675c-c538-4f95-969a-ff9170b794ca`::moving from state preparing -> state finished
Thread-192::DEBUG::2015-02-25 20:10:26,256::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-733::DEBUG::2015-02-25 20:10:26,261::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-192::DEBUG::2015-02-25 20:10:26,266::task::993::Storage.TaskManager.Task::(_decref) Task=`7fc2510a-4bed-4efe-befb-8bd989b2c257`::ref 0 aborting False
Thread-733::DEBUG::2015-02-25 20:10:26,269::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-733::DEBUG::2015-02-25 20:10:26,278::task::993::Storage.TaskManager.Task::(_decref) Task=`e849675c-c538-4f95-969a-ff9170b794ca`::ref 0 aborting False
Thread-1576::DEBUG::2015-02-25 20:10:26,354::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-02-25 20:10:26,368::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-2146::DEBUG::2015-02-25 20:10:26,376::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-192::DEBUG::2015-02-25 20:10:26,432::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-733::DEBUG::2015-02-25 20:10:26,440::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-2371::DEBUG::2015-02-25 20:10:26,737::task::595::Storage.TaskManager.Task::(_updateState) Task=`507d0eec-6705-4774-aad6-6ed63b363fca`::moving from state init -> state preparing
Thread-2066::DEBUG::2015-02-25 20:10:26,738::task::595::Storage.TaskManager.Task::(_updateState) Task=`9e526b92-08fc-4b41-9171-b27c55b3aabe`::moving from state init -> state preparing
Thread-2371::INFO::2015-02-25 20:10:26,774::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='e732a82f-bae9-4368-8b98-dedc1c3814de', spUUID='00000002-0002-0002-0002-000000000145', imgUUID='c8aac4fe-6775-49bb-9235-3a49078f4214', volUUID='c2f8339c-ea41-4f8e-9d9f-0923bcedb21c', options=None)
Thread-2066::INFO::2015-02-25 20:10:26,783::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='e732a82f-bae9-4368-8b98-dedc1c3814de', spUUID='00000002-0002-0002-0002-000000000145', imgUUID='c4a03c79-da16-483c-bc3b-d8efa833f510', volUUID='47a8437b-b460-4f79-ae23-34220f6f2e2e', options=None)
Thread-2371::INFO::2015-02-25 20:10:26,882::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '1703649280', 'apparentsize': '21474836480'}
Thread-2066::INFO::2015-02-25 20:10:26,894::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '3571089408', 'apparentsize': '21474836480'}
Thread-2371::DEBUG::2015-02-25 20:10:26,894::task::1191::Storage.TaskManager.Task::(prepare) Task=`507d0eec-6705-4774-aad6-6ed63b363fca`::finished: {'truesize': '1703649280', 'apparentsize': '21474836480'}
Thread-2066::DEBUG::2015-02-25 20:10:26,897::task::1191::Storage.TaskManager.Task::(prepare) Task=`9e526b92-08fc-4b41-9171-b27c55b3aabe`::finished: {'truesize': '3571089408', 'apparentsize': '21474836480'}
Thread-2371::DEBUG::2015-02-25 20:10:26,897::task::595::Storage.TaskManager.Task::(_updateState) Task=`507d0eec-6705-4774-aad6-6ed63b363fca`::moving from state preparing -> state finished
Thread-2066::DEBUG::2015-02-25 20:10:26,898::task::595::Storage.TaskManager.Task::(_updateState) Task=`9e526b92-08fc-4b41-9171-b27c55b3aabe`::moving from state preparing -> state finished
Thread-2371::DEBUG::2015-02-25 20:10:26,899::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-2066::DEBUG::2015-02-25 20:10:26,900::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-2371::DEBUG::2015-02-25 20:10:26,900::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-2066::DEBUG::2015-02-25 20:10:26,901::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-2371::DEBUG::2015-02-25 20:10:26,902::task::993::Storage.TaskManager.Task::(_decref) Task=`507d0eec-6705-4774-aad6-6ed63b363fca`::ref 0 aborting False
Thread-2066::DEBUG::2015-02-25 20:10:26,903::task::993::Storage.TaskManager.Task::(_decref) Task=`9e526b92-08fc-4b41-9171-b27c55b3aabe`::ref 0 aborting False
Thread-2066::DEBUG::2015-02-25 20:10:27,045::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-2371::DEBUG::2015-02-25 20:10:27,046::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-56::DEBUG::2015-02-25 20:10:27,084::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-02-25 20:10:27,089::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-742::DEBUG::2015-02-25 20:10:28,041::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-2150::DEBUG::2015-02-25 20:10:28,381::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-2781::DEBUG::2015-02-25 20:10:28,382::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-590::DEBUG::2015-02-25 20:10:29,093::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-1753::DEBUG::2015-02-25 20:10:29,096::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-4574::DEBUG::2015-02-25 20:10:29,107::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-606::DEBUG::2015-02-25 20:10:31,162::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-25::DEBUG::2015-02-25 20:10:31,392::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd if=/rhev/data-center/mnt/117.18.79.72:_36Cloud__OStemplates/05be2753-83ed-4e6e-b236-4b342939a5fb/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-25::DEBUG::2015-02-25 20:10:31,635::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n345 bytes (345 B) copied, 0.000944452 s, 365 kB/s\n'; <rc> = 0
Thread-627::DEBUG::2015-02-25 20:10:31,856::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-5186::DEBUG::2015-02-25 20:10:31,857::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-4437::DEBUG::2015-02-25 20:10:31,861::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-659::DEBUG::2015-02-25 20:10:32,663::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-379::DEBUG::2015-02-25 20:10:32,817::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-1789::DEBUG::2015-02-25 20:10:33,176::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-2891::DEBUG::2015-02-25 20:10:33,393::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
VM Channels Listener::DEBUG::2015-02-25 20:10:33,438::vmchannels::96::vds::(_handle_timeouts) Timeout on fileno 203.
Thread-1219::DEBUG::2015-02-25 20:10:33,763::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-1472::DEBUG::2015-02-25 20:10:33,769::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-929::DEBUG::2015-02-25 20:10:33,812::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-1399::DEBUG::2015-02-25 20:10:34,107::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-66::DEBUG::2015-02-25 20:10:34,123::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-576::DEBUG::2015-02-25 20:10:35,405::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-1894::DEBUG::2015-02-25 20:10:35,417::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-1661::DEBUG::2015-02-25 20:10:35,633::task::595::Storage.TaskManager.Task::(_updateState) Task=`9b04bd40-0c51-433e-a0f0-66d2ad1a7c02`::moving from state init -> state preparing
Thread-1661::INFO::2015-02-25 20:10:35,634::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='e732a82f-bae9-4368-8b98-dedc1c3814de', spUUID='00000002-0002-0002-0002-000000000145', imgUUID='ec3802f3-0963-4cb5-b3cb-ebda2d6ee7e1', volUUID='ada9e758-7a65-409e-845b-6c9eb40f84fc', options=None)
Thread-1661::INFO::2015-02-25 20:10:35,662::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '2003734528', 'apparentsize': '21474836480'}
Thread-1661::DEBUG::2015-02-25 20:10:35,663::task::1191::Storage.TaskManager.Task::(prepare) Task=`9b04bd40-0c51-433e-a0f0-66d2ad1a7c02`::finished: {'truesize': '2003734528', 'apparentsize': '21474836480'}
Thread-1661::DEBUG::2015-02-25 20:10:35,666::task::595::Storage.TaskManager.Task::(_updateState) Task=`9b04bd40-0c51-433e-a0f0-66d2ad1a7c02`::moving from state preparing -> state finished
Thread-1661::DEBUG::2015-02-25 20:10:35,667::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-1661::DEBUG::2015-02-25 20:10:35,668::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-1661::DEBUG::2015-02-25 20:10:35,669::task::993::Storage.TaskManager.Task::(_decref) Task=`9b04bd40-0c51-433e-a0f0-66d2ad1a7c02`::ref 0 aborting False
Thread-386::DEBUG::2015-02-25 20:10:35,796::task::595::Storage.TaskManager.Task::(_updateState) Task=`dd92e901-eb42-47f8-a9b8-361a667f8505`::moving from state init -> state preparing
Thread-386::INFO::2015-02-25 20:10:35,796::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='e732a82f-bae9-4368-8b98-dedc1c3814de', spUUID='00000002-0002-0002-0002-000000000145', imgUUID='a1b22e46-219d-447d-ab36-e3711c889bca', volUUID='2739f665-a4d5-498f-9caa-6589c42651c6', options=None)
Thread-1661::DEBUG::2015-02-25 20:10:35,797::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-1471::DEBUG::2015-02-25 20:10:35,799::task::595::Storage.TaskManager.Task::(_updateState) Task=`dcbca6f1-ca63-498e-9d4a-20bd5aadcb32`::moving from state init -> state preparing
Thread-1471::INFO::2015-02-25 20:10:35,800::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='e732a82f-bae9-4368-8b98-dedc1c3814de', spUUID='00000002-0002-0002-0002-000000000145', imgUUID='00598186-f35f-488f-8ee2-1fba5c4f780a', volUUID='e3d7e429-5333-4536-88cf-4768f463e436', options=None)
Thread-55::DEBUG::2015-02-25 20:10:35,802::task::595::Storage.TaskManager.Task::(_updateState) Task=`e5cf37eb-56aa-4edc-b2de-c796ae4d7ce0`::moving from state init -> state preparing
Thread-55::INFO::2015-02-25 20:10:35,802::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='e732a82f-bae9-4368-8b98-dedc1c3814de', spUUID='00000002-0002-0002-0002-000000000145', imgUUID='f75b8ec4-2f9f-4882-97d3-03d776e7aa5e', volUUID='d5000eaf-de30-433f-a04d-ac127e0e3f00', options=None)
Thread-386::INFO::2015-02-25 20:10:35,824::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '1385721856', 'apparentsize': '21474836480'}
Thread-386::DEBUG::2015-02-25 20:10:35,828::task::1191::Storage.TaskManager.Task::(prepare) Task=`dd92e901-eb42-47f8-a9b8-361a667f8505`::finished: {'truesize': '1385721856', 'apparentsize': '21474836480'}
Thread-1471::INFO::2015-02-25 20:10:35,830::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '2734686208', 'apparentsize': '21474836480'}
Thread-386::DEBUG::2015-02-25 20:10:35,832::task::595::Storage.TaskManager.Task::(_updateState) Task=`dd92e901-eb42-47f8-a9b8-361a667f8505`::moving from state preparing -> state finished
Thread-55::INFO::2015-02-25 20:10:35,835::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '1800978432', 'apparentsize': '21474836480'}
Thread-1471::DEBUG::2015-02-25 20:10:35,837::task::1191::Storage.TaskManager.Task::(prepare) Task=`dcbca6f1-ca63-498e-9d4a-20bd5aadcb32`::finished: {'truesize': '2734686208', 'apparentsize': '21474836480'}
Thread-386::DEBUG::2015-02-25 20:10:35,838::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-55::DEBUG::2015-02-25 20:10:35,842::task::1191::Storage.TaskManager.Task::(prepare) Task=`e5cf37eb-56aa-4edc-b2de-c796ae4d7ce0`::finished: {'truesize': '1800978432', 'apparentsize': '21474836480'}
Thread-1471::DEBUG::2015-02-25 20:10:35,842::task::595::Storage.TaskManager.Task::(_updateState) Task=`dcbca6f1-ca63-498e-9d4a-20bd5aadcb32`::moving from state preparing -> state finished
Thread-386::DEBUG::2015-02-25 20:10:35,843::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-55::DEBUG::2015-02-25 20:10:35,846::task::595::Storage.TaskManager.Task::(_updateState) Task=`e5cf37eb-56aa-4edc-b2de-c796ae4d7ce0`::moving from state preparing -> state finished
Thread-1471::DEBUG::2015-02-25 20:10:35,847::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-386::DEBUG::2015-02-25 20:10:35,849::task::993::Storage.TaskManager.Task::(_decref) Task=`dd92e901-eb42-47f8-a9b8-361a667f8505`::ref 0 aborting False
Thread-55::DEBUG::2015-02-25 20:10:35,850::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-630::DEBUG::2015-02-25 20:10:35,852::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-1471::DEBUG::2015-02-25 20:10:35,852::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-55::DEBUG::2015-02-25 20:10:35,855::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-4595::DEBUG::2015-02-25 20:10:35,858::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-1471::DEBUG::2015-02-25 20:10:35,860::task::993::Storage.TaskManager.Task::(_decref) Task=`dcbca6f1-ca63-498e-9d4a-20bd5aadcb32`::ref 0 aborting False
Thread-55::DEBUG::2015-02-25 20:10:35,861::task::993::Storage.TaskManager.Task::(_decref) Task=`e5cf37eb-56aa-4edc-b2de-c796ae4d7ce0`::ref 0 aborting False
Thread-55::DEBUG::2015-02-25 20:10:35,974::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-185::DEBUG::2015-02-25 20:10:35,980::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-386::DEBUG::2015-02-25 20:10:35,996::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-1471::DEBUG::2015-02-25 20:10:36,173::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-505::DEBUG::2015-02-25 20:10:36,210::task::595::Storage.TaskManager.Task::(_updateState) Task=`019c99ce-31e9-474a-ac97-5f401eef2772`::moving from state init -> state preparing
Thread-481::DEBUG::2015-02-25 20:10:36,222::task::595::Storage.TaskManager.Task::(_updateState) Task=`9f72da41-371a-4c53-ba47-f18b761b4fc9`::moving from state init -> state preparing
Thread-1332::DEBUG::2015-02-25 20:10:36,223::task::595::Storage.TaskManager.Task::(_updateState) Task=`912c7e66-9760-4a69-83d5-9027641c36c5`::moving from state init -> state preparing
Thread-1843::DEBUG::2015-02-25 20:10:36,220::task::595::Storage.TaskManager.Task::(_updateState) Task=`284c065f-8f8c-4df0-83cc-8c652dcb3b63`::moving from state init -> state preparing
Thread-1713::DEBUG::2015-02-25 20:10:36,229::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-505::INFO::2015-02-25 20:10:36,282::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='e732a82f-bae9-4368-8b98-dedc1c3814de', spUUID='00000002-0002-0002-0002-000000000145', imgUUID='71ad4afe-feca-4da9-8d91-75647d68a2b1', volUUID='f1675ed0-eb21-4df3-9919-a757785eb917', options=None)
Thread-2456::DEBUG::2015-02-25 20:10:36,283::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-481::INFO::2015-02-25 20:10:36,294::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='e732a82f-bae9-4368-8b98-dedc1c3814de', spUUID='00000002-0002-0002-0002-000000000145', imgUUID='c5f103d8-2ff4-4903-b3d6-356b8a482d93', volUUID='984ca697-7982-46fe-aa6c-f3e96e44889b', options=None)
Thread-1084::DEBUG::2015-02-25 20:10:36,295::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-727::DEBUG::2015-02-25 20:10:36,307::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-1521::DEBUG::2015-02-25 20:10:36,312::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-1332::INFO::2015-02-25 20:10:36,315::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='e732a82f-bae9-4368-8b98-dedc1c3814de', spUUID='00000002-0002-0002-0002-000000000145', imgUUID='8665686e-fd6f-4ef2-9f60-04de97b64087', volUUID='1b889093-2b0b-4888-b2cb-97cefe0783e3', options=None)
Thread-3002::DEBUG::2015-02-25 20:10:36,434::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-2706::DEBUG::2015-02-25 20:10:36,434::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-1754::DEBUG::2015-02-25 20:10:36,441::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-1843::INFO::2015-02-25 20:10:36,440::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='e732a82f-bae9-4368-8b98-dedc1c3814de', spUUID='00000002-0002-0002-0002-000000000145', imgUUID='fa5869b4-d2fc-48e0-85f1-0b0121b4bd94', volUUID='ec965cfe-91c6-40cc-9a86-328173a4b72f', options=None)
Thread-422::DEBUG::2015-02-25 20:10:36,443::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-2016::DEBUG::2015-02-25 20:10:36,448::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-24::DEBUG::2015-02-25 20:10:36,494::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd if=/rhev/data-center/mnt/glusterSD/10.10.0.14:_ds01/e732a82f-bae9-4368-8b98-dedc1c3814de/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-505::INFO::2015-02-25 20:10:36,967::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '1399066624', 'apparentsize': '21474836480'}
Thread-24::DEBUG::2015-02-25 20:10:36,973::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n457 bytes (457 B) copied, 0.000520198 s, 879 kB/s\n'; <rc> = 0
Thread-481::INFO::2015-02-25 20:10:37,000::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '1461882880', 'apparentsize': '21474836480'}
Thread-505::DEBUG::2015-02-25 20:10:37,023::task::1191::Storage.TaskManager.Task::(prepare) Task=`019c99ce-31e9-474a-ac97-5f401eef2772`::finished: {'truesize': '1399066624', 'apparentsize': '21474836480'}
Thread-481::DEBUG::2015-02-25 20:10:37,044::task::1191::Storage.TaskManager.Task::(prepare) Task=`9f72da41-371a-4c53-ba47-f18b761b4fc9`::finished: {'truesize': '1461882880', 'apparentsize': '21474836480'}
Thread-505::DEBUG::2015-02-25 20:10:37,048::task::595::Storage.TaskManager.Task::(_updateState) Task=`019c99ce-31e9-474a-ac97-5f401eef2772`::moving from state preparing -> state finished
Thread-481::DEBUG::2015-02-25 20:10:37,058::task::595::Storage.TaskManager.Task::(_updateState) Task=`9f72da41-371a-4c53-ba47-f18b761b4fc9`::moving from state preparing -> state finished
Thread-1332::INFO::2015-02-25 20:10:37,058::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '1858555904', 'apparentsize': '21474836480'}
Thread-505::DEBUG::2015-02-25 20:10:37,062::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-481::DEBUG::2015-02-25 20:10:37,074::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-505::DEBUG::2015-02-25 20:10:37,084::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-1332::DEBUG::2015-02-25 20:10:37,086::task::1191::Storage.TaskManager.Task::(prepare) Task=`912c7e66-9760-4a69-83d5-9027641c36c5`::finished: {'truesize': '1858555904', 'apparentsize': '21474836480'}
Thread-481::DEBUG::2015-02-25 20:10:37,090::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-1843::INFO::2015-02-25 20:10:37,098::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '2763542528', 'apparentsize': '64424509440'}
Thread-505::DEBUG::2015-02-25 20:10:37,104::task::993::Storage.TaskManager.Task::(_decref) Task=`019c99ce-31e9-474a-ac97-5f401eef2772`::ref 0 aborting False
Thread-1332::DEBUG::2015-02-25 20:10:37,107::task::595::Storage.TaskManager.Task::(_updateState) Task=`912c7e66-9760-4a69-83d5-9027641c36c5`::moving from state preparing -> state finished
Thread-481::DEBUG::2015-02-25 20:10:37,114::task::993::Storage.TaskManager.Task::(_decref) Task=`9f72da41-371a-4c53-ba47-f18b761b4fc9`::ref 0 aborting False
Thread-1843::DEBUG::2015-02-25 20:10:37,123::task::1191::Storage.TaskManager.Task::(prepare) Task=`284c065f-8f8c-4df0-83cc-8c652dcb3b63`::finished: {'truesize': '2763542528', 'apparentsize': '64424509440'}
Thread-1332::DEBUG::2015-02-25 20:10:37,130::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-1843::DEBUG::2015-02-25 20:10:37,144::task::595::Storage.TaskManager.Task::(_updateState) Task=`284c065f-8f8c-4df0-83cc-8c652dcb3b63`::moving from state preparing -> state finished
Thread-1332::DEBUG::2015-02-25 20:10:37,149::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-1843::DEBUG::2015-02-25 20:10:37,163::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-1332::DEBUG::2015-02-25 20:10:37,175::task::993::Storage.TaskManager.Task::(_decref) Task=`912c7e66-9760-4a69-83d5-9027641c36c5`::ref 0 aborting False
Thread-1843::DEBUG::2015-02-25 20:10:37,186::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-1843::DEBUG::2015-02-25 20:10:37,230::task::993::Storage.TaskManager.Task::(_decref) Task=`284c065f-8f8c-4df0-83cc-8c652dcb3b63`::ref 0 aborting False
Thread-91::DEBUG::2015-02-25 20:10:37,276::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-540::DEBUG::2015-02-25 20:10:37,296::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-3312::DEBUG::2015-02-25 20:10:37,308::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-505::DEBUG::2015-02-25 20:10:37,384::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-481::DEBUG::2015-02-25 20:10:37,391::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-1332::DEBUG::2015-02-25 20:10:37,471::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-1843::DEBUG::2015-02-25 20:10:37,522::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-02-25 20:10:38,200::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-2687::DEBUG::2015-02-25 20:10:38,207::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-1322::DEBUG::2015-02-25 20:10:38,509::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-467::DEBUG::2015-02-25 20:10:38,510::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-2517::DEBUG::2015-02-25 20:10:38,601::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-2541::DEBUG::2015-02-25 20:10:38,607::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-2760::DEBUG::2015-02-25 20:10:38,608::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-9472::DEBUG::2015-02-25 20:10:38,990::task::595::Storage.TaskManager.Task::(_updateState) Task=`b4a44586-9084-436a-b871-24e1db00419c`::moving from state init -> state preparing
Thread-9472::INFO::2015-02-25 20:10:38,991::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-9472::INFO::2015-02-25 20:10:38,991::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'e732a82f-bae9-4368-8b98-dedc1c3814de': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000520198', 'lastCheck': '1.8', 'valid': True}, '05be2753-83ed-4e6e-b236-4b342939a5fb': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000944452', 'lastCheck': '7.3', 'valid': True}}
Thread-9472::DEBUG::2015-02-25 20:10:38,991::task::1191::Storage.TaskManager.Task::(prepare) Task=`b4a44586-9084-436a-b871-24e1db00419c`::finished: {'e732a82f-bae9-4368-8b98-dedc1c3814de': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000520198', 'lastCheck': '1.8', 'valid': True}, '05be2753-83ed-4e6e-b236-4b342939a5fb': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000944452', 'lastCheck': '7.3', 'valid': True}}
Thread-9472::DEBUG::2015-02-25 20:10:38,991::task::595::Storage.TaskManager.Task::(_updateState) Task=`b4a44586-9084-436a-b871-24e1db00419c`::moving from state preparing -> state finished
Thread-9472::DEBUG::2015-02-25 20:10:38,991::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-9472::DEBUG::2015-02-25 20:10:38,992::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-9472::DEBUG::2015-02-25 20:10:38,992::task::993::Storage.TaskManager.Task::(_decref) Task=`b4a44586-9084-436a-b871-24e1db00419c`::ref 0 aborting False
Thread-1259::DEBUG::2015-02-25 20:10:39,669::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-180::DEBUG::2015-02-25 20:10:39,738::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-1187::DEBUG::2015-02-25 20:10:39,799::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-57::DEBUG::2015-02-25 20:10:39,822::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-395::DEBUG::2015-02-25 20:10:40,224::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-4645::DEBUG::2015-02-25 20:10:40,226::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-1417::DEBUG::2015-02-25 20:10:40,228::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-1059::DEBUG::2015-02-25 20:10:40,231::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-138::DEBUG::2015-02-25 20:10:40,237::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-4731::DEBUG::2015-02-25 20:10:40,244::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-238::DEBUG::2015-02-25 20:10:40,290::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-1604::DEBUG::2015-02-25 20:10:40,382::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-199::DEBUG::2015-02-25 20:10:40,677::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-1963::DEBUG::2015-02-25 20:10:40,679::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-1438::DEBUG::2015-02-25 20:10:40,680::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-3013::DEBUG::2015-02-25 20:10:41,130::task::595::Storage.TaskManager.Task::(_updateState) Task=`7a890d2b-cab7-432f-80f5-0d42e24b540a`::moving from state init -> state preparing
Thread-3013::INFO::2015-02-25 20:10:41,130::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='e732a82f-bae9-4368-8b98-dedc1c3814de', spUUID='00000002-0002-0002-0002-000000000145', imgUUID='a735328d-497c-49ca-9db0-d83095c0ddc0', volUUID='f5e0badc-f5de-4a51-a7e7-ea52054d1d0c', options=None)
Thread-3013::INFO::2015-02-25 20:10:41,156::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '1902219264', 'apparentsize': '64424509440'}
Thread-3013::DEBUG::2015-02-25 20:10:41,157::task::1191::Storage.TaskManager.Task::(prepare) Task=`7a890d2b-cab7-432f-80f5-0d42e24b540a`::finished: {'truesize': '1902219264', 'apparentsize': '64424509440'}
Thread-3013::DEBUG::2015-02-25 20:10:41,157::task::595::Storage.TaskManager.Task::(_updateState) Task=`7a890d2b-cab7-432f-80f5-0d42e24b540a`::moving from state preparing -> state finished
Thread-3013::DEBUG::2015-02-25 20:10:41,157::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-3013::DEBUG::2015-02-25 20:10:41,157::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-3013::DEBUG::2015-02-25 20:10:41,157::task::993::Storage.TaskManager.Task::(_decref) Task=`7a890d2b-cab7-432f-80f5-0d42e24b540a`::ref 0 aborting False
Thread-3013::DEBUG::2015-02-25 20:10:41,273::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-02-25 20:10:41,510::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-2146::DEBUG::2015-02-25 20:10:41,512::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-1576::DEBUG::2015-02-25 20:10:41,513::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-192::DEBUG::2015-02-25 20:10:41,599::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-733::DEBUG::2015-02-25 20:10:41,604::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-25::DEBUG::2015-02-25 20:10:41,650::domainMonitor::209::Storage.DomainMonitorThread::(_monitorDomain) Refreshing domain 05be2753-83ed-4e6e-b236-4b342939a5fb
Thread-25::DEBUG::2015-02-25 20:10:41,659::fileSD::152::Storage.StorageDomain::(__init__) Reading domain in path /rhev/data-center/mnt/117.18.79.72:_36Cloud__OStemplates/05be2753-83ed-4e6e-b236-4b342939a5fb
Thread-25::DEBUG::2015-02-25 20:10:41,663::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with FileMetadataRW backend
Thread-25::DEBUG::2015-02-25 20:10:41,665::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Backup', 'DESCRIPTION=OS_Templates', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'POOL_UUID=00000002-0002-0002-0002-000000000145', 'REMOTE_PATH=117.18.79.72:/36Cloud_OStemplates', 'ROLE=Regular', 'SDUUID=05be2753-83ed-4e6e-b236-4b342939a5fb', 'TYPE=NFS', 'VERSION=0', '_SHA_CKSUM=11fb1120ec2275ad55aa9e23a202c2a991d596cd']
Thread-25::DEBUG::2015-02-25 20:10:41,669::fileSD::610::Storage.StorageDomain::(imageGarbageCollector) Removing remnants of deleted images []
Thread-25::INFO::2015-02-25 20:10:41,669::sd::385::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace 05be2753-83ed-4e6e-b236-4b342939a5fb_imageNS already registered
Thread-25::INFO::2015-02-25 20:10:41,669::sd::393::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace 05be2753-83ed-4e6e-b236-4b342939a5fb_volumeNS already registered
Thread-25::DEBUG::2015-02-25 20:10:41,672::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd if=/rhev/data-center/mnt/117.18.79.72:_36Cloud__OStemplates/05be2753-83ed-4e6e-b236-4b342939a5fb/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-25::DEBUG::2015-02-25 20:10:41,901::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n345 bytes (345 B) copied, 0.000768833 s, 449 kB/s\n'; <rc> = 0
Thread-2371::DEBUG::2015-02-25 20:10:42,178::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-2066::DEBUG::2015-02-25 20:10:42,181::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-56::DEBUG::2015-02-25 20:10:42,442::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-02-25 20:10:42,443::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-742::DEBUG::2015-02-25 20:10:43,127::task::595::Storage.TaskManager.Task::(_updateState) Task=`78f4a3c0-5bbb-49f6-998a-5530771d838b`::moving from state init -> state preparing
Thread-742::INFO::2015-02-25 20:10:43,178::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='e732a82f-bae9-4368-8b98-dedc1c3814de', spUUID='00000002-0002-0002-0002-000000000145', imgUUID='0fe6c51c-e516-4f2f-8943-832e2fbed2ee', volUUID='99a70d06-05c1-4402-8f38-24fb6e4e7ae3', options=None)
Thread-742::INFO::2015-02-25 20:10:43,278::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '1726410752', 'apparentsize': '21474836480'}
Thread-742::DEBUG::2015-02-25 20:10:43,289::task::1191::Storage.TaskManager.Task::(prepare) Task=`78f4a3c0-5bbb-49f6-998a-5530771d838b`::finished: {'truesize': '1726410752', 'apparentsize': '21474836480'}
Thread-742::DEBUG::2015-02-25 20:10:43,298::task::595::Storage.TaskManager.Task::(_updateState) Task=`78f4a3c0-5bbb-49f6-998a-5530771d838b`::moving from state preparing -> state finished
Thread-742::DEBUG::2015-02-25 20:10:43,307::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-742::DEBUG::2015-02-25 20:10:43,315::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-742::DEBUG::2015-02-25 20:10:43,327::task::993::Storage.TaskManager.Task::(_decref) Task=`78f4a3c0-5bbb-49f6-998a-5530771d838b`::ref 0 aborting False
Thread-2781::DEBUG::2015-02-25 20:10:43,422::task::595::Storage.TaskManager.Task::(_updateState) Task=`74a7edf8-abd5-4b40-8c75-42ee152863e5`::moving from state init -> state preparing
Thread-2150::DEBUG::2015-02-25 20:10:43,424::task::595::Storage.TaskManager.Task::(_updateState) Task=`c2182a90-ef38-417c-b16a-33dc821cfe22`::moving from state init -> state preparing
Thread-2781::INFO::2015-02-25 20:10:43,434::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='e732a82f-bae9-4368-8b98-dedc1c3814de', spUUID='00000002-0002-0002-0002-000000000145', imgUUID='ca75c558-ac28-4cd4-b1db-acde6ed96cce', volUUID='a8da2535-e69b-412a-ba39-2fd6782070d4', options=None)
Thread-2150::INFO::2015-02-25 20:10:43,437::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='e732a82f-bae9-4368-8b98-dedc1c3814de', spUUID='00000002-0002-0002-0002-000000000145', imgUUID='9c75ce80-46b2-40cc-b3f6-2075154fe427', volUUID='aebc65ce-3b5b-4696-8acd-0535541c9989', options=None)
Thread-742::DEBUG::2015-02-25 20:10:43,479::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-2781::INFO::2015-02-25 20:10:43,489::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '1550782464', 'apparentsize': '21474836480'}
Thread-2150::INFO::2015-02-25 20:10:43,500::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '1868447744', 'apparentsize': '21474836480'}
Thread-2781::DEBUG::2015-02-25 20:10:43,501::task::1191::Storage.TaskManager.Task::(prepare) Task=`74a7edf8-abd5-4b40-8c75-42ee152863e5`::finished: {'truesize': '1550782464', 'apparentsize': '21474836480'}
Thread-2150::DEBUG::2015-02-25 20:10:43,514::task::1191::Storage.TaskManager.Task::(prepare) Task=`c2182a90-ef38-417c-b16a-33dc821cfe22`::finished: {'truesize': '1868447744', 'apparentsize': '21474836480'}
Thread-2781::DEBUG::2015-02-25 20:10:43,514::task::595::Storage.TaskManager.Task::(_updateState) Task=`74a7edf8-abd5-4b40-8c75-42ee152863e5`::moving from state preparing -> state finished
Thread-2150::DEBUG::2015-02-25 20:10:43,524::task::595::Storage.TaskManager.Task::(_updateState) Task=`c2182a90-ef38-417c-b16a-33dc821cfe22`::moving from state preparing -> state finished
Thread-2781::DEBUG::2015-02-25 20:10:43,526::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-2150::DEBUG::2015-02-25 20:10:43,532::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-2781::DEBUG::2015-02-25 20:10:43,536::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-2150::DEBUG::2015-02-25 20:10:43,542::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-2781::DEBUG::2015-02-25 20:10:43,548::task::993::Storage.TaskManager.Task::(_decref) Task=`74a7edf8-abd5-4b40-8c75-42ee152863e5`::ref 0 aborting False
Thread-2150::DEBUG::2015-02-25 20:10:43,556::task::993::Storage.TaskManager.Task::(_decref) Task=`c2182a90-ef38-417c-b16a-33dc821cfe22`::ref 0 aborting False
Thread-2781::DEBUG::2015-02-25 20:10:43,704::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-2150::DEBUG::2015-02-25 20:10:43,705::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-590::DEBUG::2015-02-25 20:10:44,262::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-1753::DEBUG::2015-02-25 20:10:44,266::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-4574::DEBUG::2015-02-25 20:10:44,270::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-606::DEBUG::2015-02-25 20:10:46,264::task::595::Storage.TaskManager.Task::(_updateState) Task=`67cd6cd3-f664-4bc1-a3da-e1a592e5f16c`::moving from state init -> state preparing
Thread-606::INFO::2015-02-25 20:10:46,264::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='e732a82f-bae9-4368-8b98-dedc1c3814de', spUUID='00000002-0002-0002-0002-000000000145', imgUUID='ca0c3ef0-6e76-4123-82b9-34cefff22def', volUUID='babbb3af-0603-4dd5-a58f-2cb2daf9a5de', options=None)
Thread-606::INFO::2015-02-25 20:10:46,289::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '2159808512', 'apparentsize': '21474836480'}
Thread-606::DEBUG::2015-02-25 20:10:46,289::task::1191::Storage.TaskManager.Task::(prepare) Task=`67cd6cd3-f664-4bc1-a3da-e1a592e5f16c`::finished: {'truesize': '2159808512', 'apparentsize': '21474836480'}
Thread-606::DEBUG::2015-02-25 20:10:46,289::task::595::Storage.TaskManager.Task::(_updateState) Task=`67cd6cd3-f664-4bc1-a3da-e1a592e5f16c`::moving from state preparing -> state finished
Thread-606::DEBUG::2015-02-25 20:10:46,289::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-606::DEBUG::2015-02-25 20:10:46,289::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-606::DEBUG::2015-02-25 20:10:46,290::task::993::Storage.TaskManager.Task::(_decref) Task=`67cd6cd3-f664-4bc1-a3da-e1a592e5f16c`::ref 0 aborting False
Thread-606::DEBUG::2015-02-25 20:10:46,407::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-5186::DEBUG::2015-02-25 20:10:46,954::task::595::Storage.TaskManager.Task::(_updateState) Task=`e1ec4e4a-5705-488d-a6e9-3ace320aea09`::moving from state init -> state preparing
Thread-5186::INFO::2015-02-25 20:10:46,954::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='e732a82f-bae9-4368-8b98-dedc1c3814de', spUUID='00000002-0002-0002-0002-000000000145', imgUUID='542a4756-2d6f-41ff-a7b3-fa9ce178065e', volUUID='f54511d3-b95c-4065-a332-d4e65442c288', options=None)
Thread-627::DEBUG::2015-02-25 20:10:46,956::task::595::Storage.TaskManager.Task::(_updateState) Task=`44cb5dcf-dc96-48aa-9186-f7ad7e5476c1`::moving from state init -> state preparing
Thread-627::INFO::2015-02-25 20:10:46,957::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='e732a82f-bae9-4368-8b98-dedc1c3814de', spUUID='00000002-0002-0002-0002-000000000145', imgUUID='7aab4d26-3edd-47a2-9e44-ffcbb9a92d8e', volUUID='7a422925-b4a5-47f5-9fe4-8134bf647586', options=None)
Thread-4437::DEBUG::2015-02-25 20:10:46,959::task::595::Storage.TaskManager.Task::(_updateState) Task=`06601999-b701-4fc1-9676-96ab8303675f`::moving from state init -> state preparing
Thread-4437::INFO::2015-02-25 20:10:46,960::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='e732a82f-bae9-4368-8b98-dedc1c3814de', spUUID='00000002-0002-0002-0002-000000000145', imgUUID='0e333bcf-ca48-4fac-955b-6d62ed08b637', volUUID='ccfe7a62-79e0-4b7a-8aef-cbb1f275a774', options=None)
Thread-5186::INFO::2015-02-25 20:10:46,971::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '1233408000', 'apparentsize': '21474836480'}
Thread-5186::DEBUG::2015-02-25 20:10:46,971::task::1191::Storage.TaskManager.Task::(prepare) Task=`e1ec4e4a-5705-488d-a6e9-3ace320aea09`::finished: {'truesize': '1233408000', 'apparentsize': '21474836480'}
Thread-5186::DEBUG::2015-02-25 20:10:46,971::task::595::Storage.TaskManager.Task::(_updateState) Task=`e1ec4e4a-5705-488d-a6e9-3ace320aea09`::moving from state preparing -> state finished
Thread-5186::DEBUG::2015-02-25 20:10:46,972::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-5186::DEBUG::2015-02-25 20:10:46,972::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-5186::DEBUG::2015-02-25 20:10:46,972::task::993::Storage.TaskManager.Task::(_decref) Task=`e1ec4e4a-5705-488d-a6e9-3ace320aea09`::ref 0 aborting False
Thread-627::INFO::2015-02-25 20:10:46,989::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '1670332416', 'apparentsize': '21474836480'}
Thread-627::DEBUG::2015-02-25 20:10:46,989::task::1191::Storage.TaskManager.Task::(prepare) Task=`44cb5dcf-dc96-48aa-9186-f7ad7e5476c1`::finished: {'truesize': '1670332416', 'apparentsize': '21474836480'}
Thread-627::DEBUG::2015-02-25 20:10:46,989::task::595::Storage.TaskManager.Task::(_updateState) Task=`44cb5dcf-dc96-48aa-9186-f7ad7e5476c1`::moving from state preparing -> state finished
Thread-627::DEBUG::2015-02-25 20:10:46,989::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-627::DEBUG::2015-02-25 20:10:46,989::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-627::DEBUG::2015-02-25 20:10:46,990::task::993::Storage.TaskManager.Task::(_decref) Task=`44cb5dcf-dc96-48aa-9186-f7ad7e5476c1`::ref 0 aborting False
Thread-4437::INFO::2015-02-25 20:10:46,994::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '2159915008', 'apparentsize': '21474836480'}
Thread-4437::DEBUG::2015-02-25 20:10:46,994::task::1191::Storage.TaskManager.Task::(prepare) Task=`06601999-b701-4fc1-9676-96ab8303675f`::finished: {'truesize': '2159915008', 'apparentsize': '21474836480'}
Thread-4437::DEBUG::2015-02-25 20:10:46,994::task::595::Storage.TaskManager.Task::(_updateState) Task=`06601999-b701-4fc1-9676-96ab8303675f`::moving from state preparing -> state finished
Thread-4437::DEBUG::2015-02-25 20:10:46,994::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-4437::DEBUG::2015-02-25 20:10:46,995::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-4437::DEBUG::2015-02-25 20:10:46,995::task::993::Storage.TaskManager.Task::(_decref) Task=`06601999-b701-4fc1-9676-96ab8303675f`::ref 0 aborting False
Thread-5186::DEBUG::2015-02-25 20:10:47,120::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-627::DEBUG::2015-02-25 20:10:47,126::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-4437::DEBUG::2015-02-25 20:10:47,141::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-24::DEBUG::2015-02-25 20:10:47,233::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd if=/rhev/data-center/mnt/glusterSD/10.10.0.14:_ds01/e732a82f-bae9-4368-8b98-dedc1c3814de/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-24::DEBUG::2015-02-25 20:10:47,461::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n457 bytes (457 B) copied, 0.000454804 s, 1.0 MB/s\n'; <rc> = 0
Thread-659::DEBUG::2015-02-25 20:10:47,711::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-379::DEBUG::2015-02-25 20:10:47,955::task::595::Storage.TaskManager.Task::(_updateState) Task=`2a7c88e8-8c18-4737-894b-c82d20f7c111`::moving from state init -> state preparing
Thread-379::INFO::2015-02-25 20:10:47,990::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='e732a82f-bae9-4368-8b98-dedc1c3814de', spUUID='00000002-0002-0002-0002-000000000145', imgUUID='9ee10339-358c-4b24-9b54-cd13d8bb047f', volUUID='b38ff11f-5efe-42db-a96e-8c69f2e75b5c', options=None)
Thread-1789::DEBUG::2015-02-25 20:10:48,382::task::595::Storage.TaskManager.Task::(_updateState) Task=`52a1cf85-b356-488a-8bb0-8503c72232a0`::moving from state init -> state preparing
Thread-379::INFO::2015-02-25 20:10:48,462::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '1718005760', 'apparentsize': '21474836480'}
Thread-1789::INFO::2015-02-25 20:10:48,485::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='e732a82f-bae9-4368-8b98-dedc1c3814de', spUUID='00000002-0002-0002-0002-000000000145', imgUUID='0a3bc2c2-2218-43b5-bb22-c9c46b7c1a4d', volUUID='3e15f376-80e6-4d4e-8956-769dcd4fa69a', options=None)
Thread-379::DEBUG::2015-02-25 20:10:48,573::task::1191::Storage.TaskManager.Task::(prepare) Task=`2a7c88e8-8c18-4737-894b-c82d20f7c111`::finished: {'truesize': '1718005760', 'apparentsize': '21474836480'}
Thread-2891::DEBUG::2015-02-25 20:10:48,621::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-379::DEBUG::2015-02-25 20:10:48,641::task::595::Storage.TaskManager.Task::(_updateState) Task=`2a7c88e8-8c18-4737-894b-c82d20f7c111`::moving from state preparing -> state finished
Thread-379::DEBUG::2015-02-25 20:10:48,732::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-379::DEBUG::2015-02-25 20:10:48,795::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-1789::INFO::2015-02-25 20:10:48,853::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '1789825024', 'apparentsize': '21474836480'}
Thread-379::DEBUG::2015-02-25 20:10:48,866::task::993::Storage.TaskManager.Task::(_decref) Task=`2a7c88e8-8c18-4737-894b-c82d20f7c111`::ref 0 aborting False
Thread-1789::DEBUG::2015-02-25 20:10:48,924::task::1191::Storage.TaskManager.Task::(prepare) Task=`52a1cf85-b356-488a-8bb0-8503c72232a0`::finished: {'truesize': '1789825024', 'apparentsize': '21474836480'}
Thread-1789::DEBUG::2015-02-25 20:10:48,974::task::595::Storage.TaskManager.Task::(_updateState) Task=`52a1cf85-b356-488a-8bb0-8503c72232a0`::moving from state preparing -> state finished
Thread-1789::DEBUG::2015-02-25 20:10:49,015::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-1789::DEBUG::2015-02-25 20:10:49,042::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-1472::DEBUG::2015-02-25 20:10:49,054::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-929::DEBUG::2015-02-25 20:10:49,056::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-1219::DEBUG::2015-02-25 20:10:49,057::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-1789::DEBUG::2015-02-25 20:10:49,061::task::993::Storage.TaskManager.Task::(_decref) Task=`52a1cf85-b356-488a-8bb0-8503c72232a0`::ref 0 aborting False
Thread-379::DEBUG::2015-02-25 20:10:49,118::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-1789::DEBUG::2015-02-25 20:10:49,203::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-66::DEBUG::2015-02-25 20:10:49,304::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present
Thread-1399::DEBUG::2015-02-25 20:10:49,311::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present