periodic/591467::DEBUG::2016-09-15 11:17:23,717::task::1191::Storage.TaskManager.Task::(prepare) Task=`78742a4c-5b75-456b-a04e-ed6af5cabd5f`::finished: {'truesize': '12394496', 'apparentsize': '12386304'} periodic/591467::DEBUG::2016-09-15 11:17:23,717::task::595::Storage.TaskManager.Task::(_updateState) Task=`78742a4c-5b75-456b-a04e-ed6af5cabd5f`::moving from state preparing -> state finished periodic/591467::DEBUG::2016-09-15 11:17:23,717::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} periodic/591467::DEBUG::2016-09-15 11:17:23,718::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} periodic/591467::DEBUG::2016-09-15 11:17:23,718::task::993::Storage.TaskManager.Task::(_decref) Task=`78742a4c-5b75-456b-a04e-ed6af5cabd5f`::ref 0 aborting False periodic/591467::DEBUG::2016-09-15 11:17:23,718::task::595::Storage.TaskManager.Task::(_updateState) Task=`e7350258-60a9-4594-9b5c-93240aaffe74`::moving from state init -> state preparing periodic/591467::INFO::2016-09-15 11:17:23,718::logUtils::48::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID=u'c86d8409-4dd6-4e30-86dc-b5175a7ceb86', spUUID=u'94ed7a19-fade-4bd6-83f2-2cbb2f730b95', imgUUID=u'27dd38f9-0006-41b2-89be-02b677db7f14', volUUID=u'cc600789-de84-49ee-9bd7-f79782995465', options=None) periodic/591470::INFO::2016-09-15 11:17:23,719::logUtils::51::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '89133056', 'apparentsize': '26843545600'} periodic/591470::DEBUG::2016-09-15 11:17:23,720::task::1191::Storage.TaskManager.Task::(prepare) Task=`55615657-4734-4120-95d8-51e708287b79`::finished: {'truesize': '89133056', 'apparentsize': '26843545600'} periodic/591470::DEBUG::2016-09-15 11:17:23,720::task::595::Storage.TaskManager.Task::(_updateState) Task=`55615657-4734-4120-95d8-51e708287b79`::moving from state preparing -> state finished periodic/591470::DEBUG::2016-09-15 11:17:23,720::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} periodic/591470::DEBUG::2016-09-15 11:17:23,720::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} periodic/591470::DEBUG::2016-09-15 11:17:23,720::task::993::Storage.TaskManager.Task::(_decref) Task=`55615657-4734-4120-95d8-51e708287b79`::ref 0 aborting False periodic/591470::DEBUG::2016-09-15 11:17:23,720::task::595::Storage.TaskManager.Task::(_updateState) Task=`5a23b615-2c13-41f8-9073-1d2d104eb0aa`::moving from state init -> state preparing periodic/591470::INFO::2016-09-15 11:17:23,720::logUtils::48::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID=u'47202573-6e83-42fd-a274-d11f05eca2dd', spUUID=u'94ed7a19-fade-4bd6-83f2-2cbb2f730b95', imgUUID=u'b8cafa27-8f10-4886-ae27-0387ecc066ac', volUUID=u'cf8792ee-cf52-4814-bb55-ccde4dfd07e0', options=None) periodic/591483::INFO::2016-09-15 11:17:23,721::logUtils::51::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '30351360', 'apparentsize': '30343168'} periodic/591483::DEBUG::2016-09-15 11:17:23,721::task::1191::Storage.TaskManager.Task::(prepare) Task=`f349c482-6788-492f-a52c-a2abf62d03bb`::finished: {'truesize': '30351360', 'apparentsize': '30343168'} periodic/591483::DEBUG::2016-09-15 11:17:23,721::task::595::Storage.TaskManager.Task::(_updateState) Task=`f349c482-6788-492f-a52c-a2abf62d03bb`::moving from state preparing -> state finished periodic/591483::DEBUG::2016-09-15 11:17:23,721::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} periodic/591483::DEBUG::2016-09-15 11:17:23,721::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} periodic/591483::DEBUG::2016-09-15 11:17:23,721::task::993::Storage.TaskManager.Task::(_decref) Task=`f349c482-6788-492f-a52c-a2abf62d03bb`::ref 0 aborting False periodic/591483::DEBUG::2016-09-15 11:17:23,722::task::595::Storage.TaskManager.Task::(_updateState) Task=`7e634a37-7f95-4435-baee-050007b59729`::moving from state init -> state preparing periodic/591483::INFO::2016-09-15 11:17:23,722::logUtils::48::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID=u'47202573-6e83-42fd-a274-d11f05eca2dd', spUUID=u'94ed7a19-fade-4bd6-83f2-2cbb2f730b95', imgUUID=u'4e708243-97c3-4279-a32a-cb463e5e43a7', volUUID=u'b2125f8b-57ff-4f05-9799-8a0a7605082f', options=None) periodic/591467::INFO::2016-09-15 11:17:23,723::logUtils::51::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '1001988096', 'apparentsize': '1001914368'} periodic/591467::DEBUG::2016-09-15 11:17:23,723::task::1191::Storage.TaskManager.Task::(prepare) Task=`e7350258-60a9-4594-9b5c-93240aaffe74`::finished: {'truesize': '1001988096', 'apparentsize': '1001914368'} periodic/591467::DEBUG::2016-09-15 11:17:23,723::task::595::Storage.TaskManager.Task::(_updateState) Task=`e7350258-60a9-4594-9b5c-93240aaffe74`::moving from state preparing -> state finished periodic/591467::DEBUG::2016-09-15 11:17:23,723::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} periodic/591467::DEBUG::2016-09-15 11:17:23,723::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} periodic/591467::DEBUG::2016-09-15 11:17:23,724::task::993::Storage.TaskManager.Task::(_decref) Task=`e7350258-60a9-4594-9b5c-93240aaffe74`::ref 0 aborting False periodic/591467::DEBUG::2016-09-15 11:17:23,724::task::595::Storage.TaskManager.Task::(_updateState) Task=`2f89c802-7738-4413-8846-6b04673c0e05`::moving from state init -> state preparing periodic/591467::INFO::2016-09-15 11:17:23,724::logUtils::48::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID=u'c86d8409-4dd6-4e30-86dc-b5175a7ceb86', spUUID=u'94ed7a19-fade-4bd6-83f2-2cbb2f730b95', imgUUID=u'eb6f7b05-b1ba-4b6c-84e3-3c2ddf02c3d4', volUUID=u'2cf1c4e6-8d57-4cb0-ade3-e00c39f49805', options=None) periodic/591470::INFO::2016-09-15 11:17:23,725::logUtils::51::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '2311065600', 'apparentsize': '53687091200'} periodic/591470::DEBUG::2016-09-15 11:17:23,726::task::1191::Storage.TaskManager.Task::(prepare) Task=`5a23b615-2c13-41f8-9073-1d2d104eb0aa`::finished: {'truesize': '2311065600', 'apparentsize': '53687091200'} periodic/591470::DEBUG::2016-09-15 11:17:23,726::task::595::Storage.TaskManager.Task::(_updateState) Task=`5a23b615-2c13-41f8-9073-1d2d104eb0aa`::moving from state preparing -> state finished periodic/591470::DEBUG::2016-09-15 11:17:23,726::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} periodic/591470::DEBUG::2016-09-15 11:17:23,726::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} periodic/591470::DEBUG::2016-09-15 11:17:23,726::task::993::Storage.TaskManager.Task::(_decref) Task=`5a23b615-2c13-41f8-9073-1d2d104eb0aa`::ref 0 aborting False periodic/591483::INFO::2016-09-15 11:17:23,726::logUtils::51::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '2621440', 'apparentsize': '2621440'} periodic/591483::DEBUG::2016-09-15 11:17:23,726::task::1191::Storage.TaskManager.Task::(prepare) Task=`7e634a37-7f95-4435-baee-050007b59729`::finished: {'truesize': '2621440', 'apparentsize': '2621440'} periodic/591483::DEBUG::2016-09-15 11:17:23,726::task::595::Storage.TaskManager.Task::(_updateState) Task=`7e634a37-7f95-4435-baee-050007b59729`::moving from state preparing -> state finished periodic/591483::DEBUG::2016-09-15 11:17:23,727::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} periodic/591483::DEBUG::2016-09-15 11:17:23,727::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} periodic/591483::DEBUG::2016-09-15 11:17:23,727::task::993::Storage.TaskManager.Task::(_decref) Task=`7e634a37-7f95-4435-baee-050007b59729`::ref 0 aborting False periodic/591483::DEBUG::2016-09-15 11:17:23,727::task::595::Storage.TaskManager.Task::(_updateState) Task=`1803e54c-bc0e-4f77-b67c-763d20504020`::moving from state init -> state preparing periodic/591483::INFO::2016-09-15 11:17:23,727::logUtils::48::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID=u'47202573-6e83-42fd-a274-d11f05eca2dd', spUUID=u'94ed7a19-fade-4bd6-83f2-2cbb2f730b95', imgUUID=u'7e3906ad-7c6b-471d-8589-4cc74ba81b1f', volUUID=u'a00c9df0-8800-4aab-b6b0-a6e42f2f155f', options=None) periodic/591467::INFO::2016-09-15 11:17:23,728::logUtils::51::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '6862217216', 'apparentsize': '6862274560'} periodic/591467::DEBUG::2016-09-15 11:17:23,728::task::1191::Storage.TaskManager.Task::(prepare) Task=`2f89c802-7738-4413-8846-6b04673c0e05`::finished: {'truesize': '6862217216', 'apparentsize': '6862274560'} periodic/591467::DEBUG::2016-09-15 11:17:23,728::task::595::Storage.TaskManager.Task::(_updateState) Task=`2f89c802-7738-4413-8846-6b04673c0e05`::moving from state preparing -> state finished periodic/591467::DEBUG::2016-09-15 11:17:23,728::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} periodic/591467::DEBUG::2016-09-15 11:17:23,729::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} periodic/591467::DEBUG::2016-09-15 11:17:23,729::task::993::Storage.TaskManager.Task::(_decref) Task=`2f89c802-7738-4413-8846-6b04673c0e05`::ref 0 aborting False periodic/591483::INFO::2016-09-15 11:17:23,729::logUtils::51::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '1350217728', 'apparentsize': '1350041600'} periodic/591483::DEBUG::2016-09-15 11:17:23,729::task::1191::Storage.TaskManager.Task::(prepare) Task=`1803e54c-bc0e-4f77-b67c-763d20504020`::finished: {'truesize': '1350217728', 'apparentsize': '1350041600'} periodic/591483::DEBUG::2016-09-15 11:17:23,730::task::595::Storage.TaskManager.Task::(_updateState) Task=`1803e54c-bc0e-4f77-b67c-763d20504020`::moving from state preparing -> state finished periodic/591483::DEBUG::2016-09-15 11:17:23,730::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} periodic/591483::DEBUG::2016-09-15 11:17:23,730::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} periodic/591483::DEBUG::2016-09-15 11:17:23,730::task::993::Storage.TaskManager.Task::(_decref) Task=`1803e54c-bc0e-4f77-b67c-763d20504020`::ref 0 aborting False periodic/591483::DEBUG::2016-09-15 11:17:23,730::task::595::Storage.TaskManager.Task::(_updateState) Task=`815845a8-be52-4916-9f7f-e159ceaa4ecf`::moving from state init -> state preparing periodic/591483::INFO::2016-09-15 11:17:23,730::logUtils::48::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID=u'47202573-6e83-42fd-a274-d11f05eca2dd', spUUID=u'94ed7a19-fade-4bd6-83f2-2cbb2f730b95', imgUUID=u'4d00064a-ee20-4f3c-aa48-9cd303af7d8d', volUUID=u'73901c65-1eff-492a-94f2-03bd688f5aa8', options=None) periodic/591483::INFO::2016-09-15 11:17:23,731::logUtils::51::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '524288', 'apparentsize': '524288'} periodic/591483::DEBUG::2016-09-15 11:17:23,732::task::1191::Storage.TaskManager.Task::(prepare) Task=`815845a8-be52-4916-9f7f-e159ceaa4ecf`::finished: {'truesize': '524288', 'apparentsize': '524288'} periodic/591483::DEBUG::2016-09-15 11:17:23,732::task::595::Storage.TaskManager.Task::(_updateState) Task=`815845a8-be52-4916-9f7f-e159ceaa4ecf`::moving from state preparing -> state finished periodic/591483::DEBUG::2016-09-15 11:17:23,732::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} periodic/591483::DEBUG::2016-09-15 11:17:23,732::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} periodic/591483::DEBUG::2016-09-15 11:17:23,732::task::993::Storage.TaskManager.Task::(_decref) Task=`815845a8-be52-4916-9f7f-e159ceaa4ecf`::ref 0 aborting False jsonrpc.Executor/1::DEBUG::2016-09-15 11:17:24,281::task::595::Storage.TaskManager.Task::(_updateState) Task=`1e126ad0-01ac-4111-880f-9cd0fa43da0c`::moving from state init -> state preparing jsonrpc.Executor/1::INFO::2016-09-15 11:17:24,281::logUtils::48::dispatcher::(wrapper) Run and protect: repoStats(options=None) jsonrpc.Executor/1::INFO::2016-09-15 11:17:24,281::logUtils::51::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'272ec473-6041-42ee-bd1a-732789dd18d4': {'code': 0, 'actual': True, 'version': 3, 'acquired': True, 'delay': '0.000216693', 'lastCheck': '6.2', 'valid': True}, '47202573-6e83-42fd-a274-d11f05eca2dd': {'code': 0, 'actual': True, 'version': 3, 'acquired': True, 'delay': '0.000321449', 'lastCheck': '0.8', 'valid': True}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000186619', 'lastCheck': '6.2', 'valid': True}, '63041fa9-e093-4b44-b36f-f39f16d3974f': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000252958', 'lastCheck': '6.2', 'valid': True}, '2c51d320-88ce-4f23-8215-e15f55f66906': {'code': 0, 'actual': True, 'version': 3, 'acquired': True, 'delay': '0.00020756', 'lastCheck': '4.6', 'valid': True}, 'c86d8409-4dd6-4e30-86dc-b5175a7ceb86': {'code': 0, 'actual': True, 'version': 3, 'acquired': True, 'delay': '0.0321682', 'lastCheck': '1.9', 'valid': True}} jsonrpc.Executor/1::DEBUG::2016-09-15 11:17:24,281::task::1191::Storage.TaskManager.Task::(prepare) Task=`1e126ad0-01ac-4111-880f-9cd0fa43da0c`::finished: {'272ec473-6041-42ee-bd1a-732789dd18d4': {'code': 0, 'actual': True, 'version': 3, 'acquired': True, 'delay': '0.000216693', 'lastCheck': '6.2', 'valid': True}, '47202573-6e83-42fd-a274-d11f05eca2dd': {'code': 0, 'actual': True, 'version': 3, 'acquired': True, 'delay': '0.000321449', 'lastCheck': '0.8', 'valid': True}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000186619', 'lastCheck': '6.2', 'valid': True}, '63041fa9-e093-4b44-b36f-f39f16d3974f': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000252958', 'lastCheck': '6.2', 'valid': True}, '2c51d320-88ce-4f23-8215-e15f55f66906': {'code': 0, 'actual': True, 'version': 3, 'acquired': True, 'delay': '0.00020756', 'lastCheck': '4.6', 'valid': True}, 'c86d8409-4dd6-4e30-86dc-b5175a7ceb86': {'code': 0, 'actual': True, 'version': 3, 'acquired': True, 'delay': '0.0321682', 'lastCheck': '1.9', 'valid': True}} jsonrpc.Executor/1::DEBUG::2016-09-15 11:17:24,282::task::595::Storage.TaskManager.Task::(_updateState) Task=`1e126ad0-01ac-4111-880f-9cd0fa43da0c`::moving from state preparing -> state finished jsonrpc.Executor/1::DEBUG::2016-09-15 11:17:24,282::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} jsonrpc.Executor/1::DEBUG::2016-09-15 11:17:24,282::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} jsonrpc.Executor/1::DEBUG::2016-09-15 11:17:24,282::task::993::Storage.TaskManager.Task::(_decref) Task=`1e126ad0-01ac-4111-880f-9cd0fa43da0c`::ref 0 aborting False Reactor thread::INFO::2016-09-15 11:17:24,641::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:46331 Reactor thread::DEBUG::2016-09-15 11:17:24,646::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11 Reactor thread::INFO::2016-09-15 11:17:24,647::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:46331 Reactor thread::DEBUG::2016-09-15 11:17:24,647::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 46331) BindingXMLRPC::INFO::2016-09-15 11:17:24,647::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:46331 Thread-15824354::INFO::2016-09-15 11:17:24,648::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:46331 started Thread-15824354::DEBUG::2016-09-15 11:17:24,648::bindingxmlrpc::1262::vds::(wrapper) client [127.0.0.1]::call vmGetIoTunePolicy with ('26afde81-07e2-46df-b118-8c72cb876227',) {} Thread-15824354::DEBUG::2016-09-15 11:17:24,649::bindingxmlrpc::1269::vds::(wrapper) return vmGetIoTunePolicy with {'ioTunePolicy': [], 'status': {'message': 'Done', 'code': 0}} Thread-15824354::INFO::2016-09-15 11:17:24,650::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:46331 stopped Reactor thread::INFO::2016-09-15 11:17:24,650::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:46332 Reactor thread::DEBUG::2016-09-15 11:17:24,656::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11 Reactor thread::INFO::2016-09-15 11:17:24,656::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:46332 Reactor thread::DEBUG::2016-09-15 11:17:24,656::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 46332) BindingXMLRPC::INFO::2016-09-15 11:17:24,657::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:46332 Thread-15824355::INFO::2016-09-15 11:17:24,657::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:46332 started Thread-15824355::DEBUG::2016-09-15 11:17:24,657::bindingxmlrpc::1262::vds::(wrapper) client [127.0.0.1]::call vmGetIoTune with ('26afde81-07e2-46df-b118-8c72cb876227',) {} Thread-15824355::DEBUG::2016-09-15 11:17:24,662::bindingxmlrpc::1269::vds::(wrapper) return vmGetIoTune with {'ioTune': [{'ioTune': {'write_bytes_sec': 0L, 'total_iops_sec': 0L, 'read_iops_sec': 0L, 'read_bytes_sec': 0L, 'write_iops_sec': 0L, 'total_bytes_sec': 0L}, 'path': u'/rhev/data-center/94ed7a19-fade-4bd6-83f2-2cbb2f730b95/47202573-6e83-42fd-a274-d11f05eca2dd/images/125baba5-2bb1-443a-b457-bf74687481f5/3d9b0244-fe0a-46dc-936d-4485166f821d', 'name': u'vda'}, {'ioTune': {'write_bytes_sec': 0L, 'total_iops_sec': 0L, 'read_iops_sec': 0L, 'read_bytes_sec': 0L, 'write_iops_sec': 0L, 'total_bytes_sec': 0L}, 'path': u'/rhev/data-center/94ed7a19-fade-4bd6-83f2-2cbb2f730b95/47202573-6e83-42fd-a274-d11f05eca2dd/images/c471fa5b-4591-425a-bc33-c8644a0fd12c/2f974f55-842c-492b-8c04-8ed0a8ebaf93', 'name': u'vdb'}], 'status': {'message': 'Done', 'code': 0}} Thread-15824355::INFO::2016-09-15 11:17:24,664::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:46332 stopped Reactor thread::INFO::2016-09-15 11:17:25,747::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:46333 Reactor thread::DEBUG::2016-09-15 11:17:25,753::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11 Reactor thread::INFO::2016-09-15 11:17:25,754::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:46333 Reactor thread::DEBUG::2016-09-15 11:17:25,754::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 46333) BindingXMLRPC::INFO::2016-09-15 11:17:25,754::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:46333 Thread-15824356::INFO::2016-09-15 11:17:25,755::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:46333 started Thread-15824356::DEBUG::2016-09-15 11:17:25,755::bindingxmlrpc::1262::vds::(wrapper) client [127.0.0.1]::call vmGetIoTunePolicy with ('76378288-3fc8-4321-a904-fb576318d881',) {} Thread-15824356::DEBUG::2016-09-15 11:17:25,756::bindingxmlrpc::1269::vds::(wrapper) return vmGetIoTunePolicy with {'ioTunePolicy': [], 'status': {'message': 'Done', 'code': 0}} Thread-15824356::INFO::2016-09-15 11:17:25,757::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:46333 stopped Reactor thread::INFO::2016-09-15 11:17:25,758::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:46334 Reactor thread::DEBUG::2016-09-15 11:17:25,764::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11 Reactor thread::INFO::2016-09-15 11:17:25,764::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:46334 Reactor thread::DEBUG::2016-09-15 11:17:25,765::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 46334) BindingXMLRPC::INFO::2016-09-15 11:17:25,765::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:46334 Thread-15824357::INFO::2016-09-15 11:17:25,765::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:46334 started Thread-15824357::DEBUG::2016-09-15 11:17:25,766::bindingxmlrpc::1262::vds::(wrapper) client [127.0.0.1]::call vmGetIoTune with ('76378288-3fc8-4321-a904-fb576318d881',) {} Thread-15824357::DEBUG::2016-09-15 11:17:25,768::bindingxmlrpc::1269::vds::(wrapper) return vmGetIoTune with {'ioTune': [{'ioTune': {'write_bytes_sec': 0L, 'total_iops_sec': 0L, 'read_iops_sec': 0L, 'read_bytes_sec': 0L, 'write_iops_sec': 0L, 'total_bytes_sec': 0L}, 'path': u'/rhev/data-center/94ed7a19-fade-4bd6-83f2-2cbb2f730b95/47202573-6e83-42fd-a274-d11f05eca2dd/images/8da41c96-a35e-4ca6-a256-92a67b280397/73ddde8b-9b5a-469a-8098-4d867dadf95c', 'name': u'sda'}], 'status': {'message': 'Done', 'code': 0}} Thread-15824357::INFO::2016-09-15 11:17:25,770::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:46334 stopped Thread-12785652::DEBUG::2016-09-15 11:17:28,117::fileSD::173::Storage.Misc.excCmd::(getReadDelay) /usr/bin/taskset --cpu-list 0-31 /usr/bin/dd if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtEXP/63041fa9-e093-4b44-b36f-f39f16d3974f/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None) Thread-12785645::DEBUG::2016-09-15 11:17:28,163::fileSD::173::Storage.Misc.excCmd::(getReadDelay) /usr/bin/taskset --cpu-list 0-31 /usr/bin/dd if=/rhev/data-center/mnt/10.10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None) Thread-12785652::DEBUG::2016-09-15 11:17:28,207::fileSD::173::Storage.Misc.excCmd::(getReadDelay) SUCCESS: = '0+1 records in\n0+1 records out\n363 bytes (363 B) copied, 0.000295665 s, 1.2 MB/s\n'; = 0 Thread-12785648::DEBUG::2016-09-15 11:17:28,208::fileSD::173::Storage.Misc.excCmd::(getReadDelay) /usr/bin/taskset --cpu-list 0-31 /usr/bin/dd if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtISO/bff3a2be-fdd9-4e37-b416-fa4ef7fafba2/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None) Thread-12785645::DEBUG::2016-09-15 11:17:28,254::fileSD::173::Storage.Misc.excCmd::(getReadDelay) SUCCESS: = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.000189359 s, 2.9 MB/s\n'; = 0 Thread-12785648::DEBUG::2016-09-15 11:17:28,257::fileSD::173::Storage.Misc.excCmd::(getReadDelay) SUCCESS: = '0+1 records in\n0+1 records out\n357 bytes (357 B) copied, 0.00024887 s, 1.4 MB/s\n'; = 0 Thread-12785623::DEBUG::2016-09-15 11:17:29,674::fileSD::173::Storage.Misc.excCmd::(getReadDelay) /usr/bin/taskset --cpu-list 0-31 /usr/bin/dd if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtIB/2c51d320-88ce-4f23-8215-e15f55f66906/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None) Thread-12785623::DEBUG::2016-09-15 11:17:29,720::fileSD::173::Storage.Misc.excCmd::(getReadDelay) SUCCESS: = '0+1 records in\n0+1 records out\n690 bytes (690 B) copied, 0.000200544 s, 3.4 MB/s\n'; = 0 VM Channels Listener::DEBUG::2016-09-15 11:17:30,385::guestagent::309::virt.vm::(_handleMessage) vmId=`26afde81-07e2-46df-b118-8c72cb876227`::username: u'admin@colzks01' Reactor thread::INFO::2016-09-15 11:17:30,780::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:46335 Reactor thread::DEBUG::2016-09-15 11:17:30,787::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11 Reactor thread::INFO::2016-09-15 11:17:30,787::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:46335 Reactor thread::DEBUG::2016-09-15 11:17:30,787::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 46335) BindingXMLRPC::INFO::2016-09-15 11:17:30,787::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:46335 Thread-15824358::INFO::2016-09-15 11:17:30,788::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:46335 started Thread-15824358::INFO::2016-09-15 11:17:30,816::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:46335 stopped Reactor thread::INFO::2016-09-15 11:17:30,816::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:46336 Reactor thread::DEBUG::2016-09-15 11:17:30,822::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11 Reactor thread::INFO::2016-09-15 11:17:30,822::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:46336 Reactor thread::DEBUG::2016-09-15 11:17:30,822::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 46336) BindingXMLRPC::INFO::2016-09-15 11:17:30,823::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:46336 Thread-15824359::INFO::2016-09-15 11:17:30,823::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:46336 started Thread-15824359::DEBUG::2016-09-15 11:17:30,823::bindingxmlrpc::1262::vds::(wrapper) client [127.0.0.1]::call vmGetIoTunePolicy with ('df64850b-eb40-4fd3-a54b-bcbd0bcb386b',) {} Thread-15824359::DEBUG::2016-09-15 11:17:30,824::bindingxmlrpc::1269::vds::(wrapper) return vmGetIoTunePolicy with {'ioTunePolicy': [], 'status': {'message': 'Done', 'code': 0}} Thread-15824359::INFO::2016-09-15 11:17:30,825::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:46336 stopped Reactor thread::INFO::2016-09-15 11:17:30,825::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:46337 Reactor thread::DEBUG::2016-09-15 11:17:30,831::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11 Reactor thread::INFO::2016-09-15 11:17:30,831::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:46337 Reactor thread::DEBUG::2016-09-15 11:17:30,831::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 46337) BindingXMLRPC::INFO::2016-09-15 11:17:30,832::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:46337 Thread-15824360::INFO::2016-09-15 11:17:30,832::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:46337 started Thread-15824360::DEBUG::2016-09-15 11:17:30,832::bindingxmlrpc::1262::vds::(wrapper) client [127.0.0.1]::call vmGetIoTune with ('df64850b-eb40-4fd3-a54b-bcbd0bcb386b',) {} Thread-15824360::DEBUG::2016-09-15 11:17:30,837::bindingxmlrpc::1269::vds::(wrapper) return vmGetIoTune with {'ioTune': [{'ioTune': {'write_bytes_sec': 0L, 'total_iops_sec': 0L, 'read_iops_sec': 0L, 'read_bytes_sec': 0L, 'write_iops_sec': 0L, 'total_bytes_sec': 0L}, 'path': u'/rhev/data-center/94ed7a19-fade-4bd6-83f2-2cbb2f730b95/c86d8409-4dd6-4e30-86dc-b5175a7ceb86/images/96a1c863-f9fd-4778-bedf-3cae66f8331b/e0648bf3-3552-4a4d-976e-eee9ccf0ac3e', 'name': u'vda'}, {'ioTune': {'write_bytes_sec': 0L, 'total_iops_sec': 0L, 'read_iops_sec': 0L, 'read_bytes_sec': 0L, 'write_iops_sec': 0L, 'total_bytes_sec': 0L}, 'path': u'/rhev/data-center/94ed7a19-fade-4bd6-83f2-2cbb2f730b95/c86d8409-4dd6-4e30-86dc-b5175a7ceb86/images/597d8ef7-5980-4ed1-9aab-92aca0456c11/be78a897-7470-464a-9971-960919d3fecf', 'name': u'vdb'}], 'status': {'message': 'Done', 'code': 0}} Thread-15824360::INFO::2016-09-15 11:17:30,839::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:46337 stopped Reactor thread::INFO::2016-09-15 11:17:30,896::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:46338 Reactor thread::INFO::2016-09-15 11:17:30,896::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:46339 Reactor thread::DEBUG::2016-09-15 11:17:30,902::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11 Reactor thread::INFO::2016-09-15 11:17:30,902::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:46338 Reactor thread::DEBUG::2016-09-15 11:17:30,902::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 46338) BindingXMLRPC::INFO::2016-09-15 11:17:30,902::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:46338 Thread-15824361::INFO::2016-09-15 11:17:30,903::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:46338 started Thread-15824361::DEBUG::2016-09-15 11:17:30,903::bindingxmlrpc::1262::vds::(wrapper) client [127.0.0.1]::call vmGetIoTunePolicy with ('78d8e8f4-df95-44e0-ba8b-0922979fb3ac',) {} Thread-15824361::DEBUG::2016-09-15 11:17:30,904::bindingxmlrpc::1269::vds::(wrapper) return vmGetIoTunePolicy with {'ioTunePolicy': [], 'status': {'message': 'Done', 'code': 0}} Thread-15824361::INFO::2016-09-15 11:17:30,905::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:46338 stopped Reactor thread::DEBUG::2016-09-15 11:17:30,907::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11 Reactor thread::INFO::2016-09-15 11:17:30,908::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:46340 Reactor thread::DEBUG::2016-09-15 11:17:30,913::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11 Reactor thread::INFO::2016-09-15 11:17:30,913::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:46339 Reactor thread::DEBUG::2016-09-15 11:17:30,913::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 46339) Reactor thread::INFO::2016-09-15 11:17:30,914::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:46341 Reactor thread::INFO::2016-09-15 11:17:30,914::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:46340 Reactor thread::DEBUG::2016-09-15 11:17:30,914::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 46340) BindingXMLRPC::INFO::2016-09-15 11:17:30,914::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:46339 BindingXMLRPC::INFO::2016-09-15 11:17:30,914::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:46340 Thread-15824362::INFO::2016-09-15 11:17:30,915::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:46339 started Thread-15824362::DEBUG::2016-09-15 11:17:30,915::bindingxmlrpc::1262::vds::(wrapper) client [127.0.0.1]::call vmGetIoTunePolicy with ('7740209b-a823-4d68-85f0-ec678f74f326',) {} Thread-15824363::INFO::2016-09-15 11:17:30,915::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:46340 started Thread-15824363::DEBUG::2016-09-15 11:17:30,916::bindingxmlrpc::1262::vds::(wrapper) client [127.0.0.1]::call vmGetIoTunePolicy with ('baab22a1-273c-4a6c-ba65-a1720ba27a7d',) {} Reactor thread::DEBUG::2016-09-15 11:17:30,929::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11 Reactor thread::INFO::2016-09-15 11:17:30,929::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:46342 Reactor thread::INFO::2016-09-15 11:17:30,929::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:46341 Reactor thread::DEBUG::2016-09-15 11:17:30,930::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 46341) BindingXMLRPC::INFO::2016-09-15 11:17:30,930::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:46341 Reactor thread::DEBUG::2016-09-15 11:17:30,943::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11 Reactor thread::INFO::2016-09-15 11:17:30,943::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:46342 Reactor thread::DEBUG::2016-09-15 11:17:30,943::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 46342) Thread-15824362::DEBUG::2016-09-15 11:17:30,957::bindingxmlrpc::1269::vds::(wrapper) return vmGetIoTunePolicy with {'ioTunePolicy': [], 'status': {'message': 'Done', 'code': 0}} Reactor thread::INFO::2016-09-15 11:17:30,982::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:46343 Reactor thread::DEBUG::2016-09-15 11:17:30,989::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11 Reactor thread::INFO::2016-09-15 11:17:30,989::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:46343 Reactor thread::DEBUG::2016-09-15 11:17:30,990::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 46343) Thread-15824362::INFO::2016-09-15 11:17:31,979::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:46339 stopped BindingXMLRPC::INFO::2016-09-15 11:17:31,988::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:46342 Thread-15824364::INFO::2016-09-15 11:17:31,988::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:46341 started Thread-15824364::DEBUG::2016-09-15 11:17:31,989::bindingxmlrpc::1262::vds::(wrapper) client [127.0.0.1]::call vmGetIoTune with ('78d8e8f4-df95-44e0-ba8b-0922979fb3ac',) {} Thread-15824363::DEBUG::2016-09-15 11:17:31,989::bindingxmlrpc::1269::vds::(wrapper) return vmGetIoTunePolicy with {'ioTunePolicy': [], 'status': {'message': 'Done', 'code': 0}} BindingXMLRPC::INFO::2016-09-15 11:17:31,990::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:46343 Thread-15824365::INFO::2016-09-15 11:17:31,990::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:46342 started Thread-15824365::DEBUG::2016-09-15 11:17:31,990::bindingxmlrpc::1262::vds::(wrapper) client [127.0.0.1]::call vmGetIoTunePolicy with ('542affb0-7a2f-4297-84f4-728a315a6abd',) {} Thread-15824363::INFO::2016-09-15 11:17:31,991::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:46340 stopped Reactor thread::INFO::2016-09-15 11:17:31,992::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:46344 Reactor thread::DEBUG::2016-09-15 11:17:31,997::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11 Reactor thread::INFO::2016-09-15 11:17:31,998::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:46344 Reactor thread::DEBUG::2016-09-15 11:17:31,998::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 46344) BindingXMLRPC::INFO::2016-09-15 11:17:32,007::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:46344 Thread-15824365::DEBUG::2016-09-15 11:17:32,007::bindingxmlrpc::1269::vds::(wrapper) return vmGetIoTunePolicy with {'ioTunePolicy': [], 'status': {'message': 'Done', 'code': 0}} Thread-15824366::INFO::2016-09-15 11:17:32,008::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:46343 started Thread-15824366::DEBUG::2016-09-15 11:17:32,008::bindingxmlrpc::1262::vds::(wrapper) client [127.0.0.1]::call vmGetIoTune with ('7740209b-a823-4d68-85f0-ec678f74f326',) {} Thread-15824365::INFO::2016-09-15 11:17:32,009::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:46342 stopped Thread-15824367::INFO::2016-09-15 11:17:32,009::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:46344 started Reactor thread::INFO::2016-09-15 11:17:32,009::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:46345 Thread-15824367::DEBUG::2016-09-15 11:17:32,010::bindingxmlrpc::1262::vds::(wrapper) client [127.0.0.1]::call vmGetIoTune with ('baab22a1-273c-4a6c-ba65-a1720ba27a7d',) {} Reactor thread::DEBUG::2016-09-15 11:17:32,015::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11 Reactor thread::INFO::2016-09-15 11:17:32,015::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:46345 Reactor thread::DEBUG::2016-09-15 11:17:32,016::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 46345) BindingXMLRPC::INFO::2016-09-15 11:17:32,016::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:46345 Thread-15824368::INFO::2016-09-15 11:17:32,032::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:46345 started Thread-15824368::DEBUG::2016-09-15 11:17:32,033::bindingxmlrpc::1262::vds::(wrapper) client [127.0.0.1]::call vmGetIoTune with ('542affb0-7a2f-4297-84f4-728a315a6abd',) {} Thread-15824366::DEBUG::2016-09-15 11:17:32,037::bindingxmlrpc::1269::vds::(wrapper) return vmGetIoTune with {'ioTune': [{'ioTune': {'write_bytes_sec': 0L, 'total_iops_sec': 0L, 'read_iops_sec': 0L, 'read_bytes_sec': 0L, 'write_iops_sec': 0L, 'total_bytes_sec': 0L}, 'path': u'/rhev/data-center/94ed7a19-fade-4bd6-83f2-2cbb2f730b95/272ec473-6041-42ee-bd1a-732789dd18d4/images/a0bd4cac-54f3-4724-8a14-69d1bf3df882/0ee9f6a2-b599-4b82-b15f-081d8ff470f3', 'name': u'vda'}, {'ioTune': {'write_bytes_sec': 0L, 'total_iops_sec': 0L, 'read_iops_sec': 0L, 'read_bytes_sec': 0L, 'write_iops_sec': 0L, 'total_bytes_sec': 0L}, 'path': u'/rhev/data-center/94ed7a19-fade-4bd6-83f2-2cbb2f730b95/272ec473-6041-42ee-bd1a-732789dd18d4/images/59cd7e6d-2166-4da4-86f7-a105f3db1ef2/af323686-38ba-4272-9faf-81c4542d1047', 'name': u'vdb'}, {'ioTune': {'write_bytes_sec': 0L, 'total_iops_sec': 0L, 'read_iops_sec': 0L, 'read_bytes_sec': 0L, 'write_iops_sec': 0L, 'total_bytes_sec': 0L}, 'path': u'/rhev/data-center/94ed7a19-fade-4bd6-83f2-2cbb2f730b95/272ec473-6041-42ee-bd1a-732789dd18d4/images/84f9fc6b-4046-4399-a7dc-a178ae187250/a2f3d606-daf0-469d-a175-e40923ad5007', 'name': u'vdc'}], 'status': {'message': 'Done', 'code': 0}} Thread-15824366::INFO::2016-09-15 11:17:32,040::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:46343 stopped Thread-15824364::DEBUG::2016-09-15 11:17:32,055::bindingxmlrpc::1269::vds::(wrapper) return vmGetIoTune with {'ioTune': [{'ioTune': {'write_bytes_sec': 0L, 'total_iops_sec': 0L, 'read_iops_sec': 0L, 'read_bytes_sec': 0L, 'write_iops_sec': 0L, 'total_bytes_sec': 0L}, 'path': u'/rhev/data-center/94ed7a19-fade-4bd6-83f2-2cbb2f730b95/47202573-6e83-42fd-a274-d11f05eca2dd/images/89d54d8f-b0dc-4fbf-a655-1ec02e2e0b7a/../89d54d8f-b0dc-4fbf-a655-1ec02e2e0b7a/d042a61a-f182-4115-8099-6ccb831e8f7d', 'name': u'vda'}, {'ioTune': {'write_bytes_sec': 0L, 'total_iops_sec': 0L, 'read_iops_sec': 0L, 'read_bytes_sec': 0L, 'write_iops_sec': 0L, 'total_bytes_sec': 0L}, 'path': u'/rhev/data-center/94ed7a19-fade-4bd6-83f2-2cbb2f730b95/47202573-6e83-42fd-a274-d11f05eca2dd/images/fce2a78d-ad4c-45fd-a640-123570c60273/../fce2a78d-ad4c-45fd-a640-123570c60273/123cd80c-96a8-4453-95cc-cf94186115ca', 'name': u'vdb'}, {'ioTune': {'write_bytes_sec': 0L, 'total_iops_sec': 0L, 'read_iops_sec': 0L, 'read_bytes_sec': 0L, 'write_iops_sec': 0L, 'total_bytes_sec': 0L}, 'path': u'/rhev/data-center/94ed7a19-fade-4bd6-83f2-2cbb2f730b95/47202573-6e83-42fd-a274-d11f05eca2dd/images/a13d1d0a-9b74-4518-84a5-36ec0e1f4dd8/../a13d1d0a-9b74-4518-84a5-36ec0e1f4dd8/42b7cc06-dc30-4101-bc9f-178f27446a9c', 'name': u'vdc'}, {'ioTune': {'write_bytes_sec': 0L, 'total_iops_sec': 0L, 'read_iops_sec': 0L, 'read_bytes_sec': 0L, 'write_iops_sec': 0L, 'total_bytes_sec': 0L}, 'path': u'/rhev/data-center/94ed7a19-fade-4bd6-83f2-2cbb2f730b95/47202573-6e83-42fd-a274-d11f05eca2dd/images/c8e793ac-b571-4a6e-9ea1-0776ef1dc56f/../c8e793ac-b571-4a6e-9ea1-0776ef1dc56f/37ee55ba-0dee-4f3f-b550-9d3293e2642b', 'name': u'vdd'}, {'ioTune': {'write_bytes_sec': 0L, 'total_iops_sec': 0L, 'read_iops_sec': 0L, 'read_bytes_sec': 0L, 'write_iops_sec': 0L, 'total_bytes_sec': 0L}, 'path': u'/rhev/data-center/94ed7a19-fade-4bd6-83f2-2cbb2f730b95/47202573-6e83-42fd-a274-d11f05eca2dd/images/b8cafa27-8f10-4886-ae27-0387ecc066ac/../b8cafa27-8f10-4886-ae27-0387ecc066ac/cf8792ee-cf52-4814-bb55-ccde4dfd07e0', 'name': u'vde'}], 'status': {'message': 'Done', 'code': 0}} Thread-15824364::INFO::2016-09-15 11:17:32,058::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:46341 stopped Thread-15824367::DEBUG::2016-09-15 11:17:32,066::bindingxmlrpc::1269::vds::(wrapper) return vmGetIoTune with {'ioTune': [{'ioTune': {'write_bytes_sec': 0L, 'total_iops_sec': 0L, 'read_iops_sec': 0L, 'read_bytes_sec': 0L, 'write_iops_sec': 0L, 'total_bytes_sec': 0L}, 'path': u'/rhev/data-center/94ed7a19-fade-4bd6-83f2-2cbb2f730b95/c86d8409-4dd6-4e30-86dc-b5175a7ceb86/images/2bddf5f6-699b-4866-91df-feaa5624f657/2b231d77-6edf-4f27-91bd-fa84b51cd7c3', 'name': u'hda'}, {'ioTune': {'write_bytes_sec': 0L, 'total_iops_sec': 0L, 'read_iops_sec': 0L, 'read_bytes_sec': 0L, 'write_iops_sec': 0L, 'total_bytes_sec': 0L}, 'path': u'/rhev/data-center/94ed7a19-fade-4bd6-83f2-2cbb2f730b95/c86d8409-4dd6-4e30-86dc-b5175a7ceb86/images/e9edf93f-f20b-4ccb-b298-45b4fa8da820/c8acdbc7-af24-4c5c-94c5-ae7262d98f5c', 'name': u'vda'}, {'ioTune': {'write_bytes_sec': 0L, 'total_iops_sec': 0L, 'read_iops_sec': 0L, 'read_bytes_sec': 0L, 'write_iops_sec': 0L, 'total_bytes_sec': 0L}, 'path': u'/rhev/data-center/94ed7a19-fade-4bd6-83f2-2cbb2f730b95/c86d8409-4dd6-4e30-86dc-b5175a7ceb86/images/1e15c99e-c351-408a-967e-c0afa288f566/53224338-154c-43a9-98e0-9acfe8c25e83', 'name': u'vdb'}, {'ioTune': {'write_bytes_sec': 0L, 'total_iops_sec': 0L, 'read_iops_sec': 0L, 'read_bytes_sec': 0L, 'write_iops_sec': 0L, 'total_bytes_sec': 0L}, 'path': u'/rhev/data-center/94ed7a19-fade-4bd6-83f2-2cbb2f730b95/c86d8409-4dd6-4e30-86dc-b5175a7ceb86/images/12015dbb-9caa-47f4-9c9f-05fb91a9fe1a/12544819-ffa3-4019-b36e-7d8df674ee4d', 'name': u'hdb'}, {'ioTune': {'write_bytes_sec': 0L, 'total_iops_sec': 0L, 'read_iops_sec': 0L, 'read_bytes_sec': 0L, 'write_iops_sec': 0L, 'total_bytes_sec': 0L}, 'path': u'/rhev/data-center/94ed7a19-fade-4bd6-83f2-2cbb2f730b95/c86d8409-4dd6-4e30-86dc-b5175a7ceb86/images/27dd38f9-0006-41b2-89be-02b677db7f14/cc600789-de84-49ee-9bd7-f79782995465', 'name': u'vdc'}, {'ioTune': {'write_bytes_sec': 0L, 'total_iops_sec': 0L, 'read_iops_sec': 0L, 'read_bytes_sec': 0L, 'write_iops_sec': 0L, 'total_bytes_sec': 0L}, 'path': u'/rhev/data-center/94ed7a19-fade-4bd6-83f2-2cbb2f730b95/c86d8409-4dd6-4e30-86dc-b5175a7ceb86/images/eb6f7b05-b1ba-4b6c-84e3-3c2ddf02c3d4/2cf1c4e6-8d57-4cb0-ade3-e00c39f49805', 'name': u'vdd'}], 'status': {'message': 'Done', 'code': 0}} Thread-15824367::INFO::2016-09-15 11:17:32,070::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:46344 stopped Thread-15824368::DEBUG::2016-09-15 11:17:32,076::bindingxmlrpc::1269::vds::(wrapper) return vmGetIoTune with {'ioTune': [{'ioTune': {'write_bytes_sec': 0L, 'total_iops_sec': 0L, 'read_iops_sec': 0L, 'read_bytes_sec': 0L, 'write_iops_sec': 0L, 'total_bytes_sec': 0L}, 'path': u'/rhev/data-center/94ed7a19-fade-4bd6-83f2-2cbb2f730b95/47202573-6e83-42fd-a274-d11f05eca2dd/images/dcd5456b-e50a-4fe2-9cc2-614a0764dfc1/90c3ef07-3aa5-4ac5-9132-4b21b53eb4f4', 'name': u'vda'}, {'ioTune': {'write_bytes_sec': 0L, 'total_iops_sec': 0L, 'read_iops_sec': 0L, 'read_bytes_sec': 0L, 'write_iops_sec': 0L, 'total_bytes_sec': 0L}, 'path': u'/rhev/data-center/94ed7a19-fade-4bd6-83f2-2cbb2f730b95/47202573-6e83-42fd-a274-d11f05eca2dd/images/531fa1b1-fbd0-42ca-9f6b-cf764c91f8a9/1ac9e32b-c5eb-4f05-a51c-e1c1fd2d9598', 'name': u'vdb'}, {'ioTune': {'write_bytes_sec': 0L, 'total_iops_sec': 0L, 'read_iops_sec': 0L, 'read_bytes_sec': 0L, 'write_iops_sec': 0L, 'total_bytes_sec': 0L}, 'path': u'/rhev/data-center/94ed7a19-fade-4bd6-83f2-2cbb2f730b95/47202573-6e83-42fd-a274-d11f05eca2dd/images/19644ad4-fe32-4b12-8bfb-d75a16fec85a/28789183-b4c7-4ddc-9d5c-de4b58f51cdd', 'name': u'vdc'}, {'ioTune': {'write_bytes_sec': 0L, 'total_iops_sec': 0L, 'read_iops_sec': 0L, 'read_bytes_sec': 0L, 'write_iops_sec': 0L, 'total_bytes_sec': 0L}, 'path': u'/rhev/data-center/94ed7a19-fade-4bd6-83f2-2cbb2f730b95/47202573-6e83-42fd-a274-d11f05eca2dd/images/f105f1cc-ab59-4c62-a465-e3ef33886c17/bb72c93b-df01-4955-88dc-00485f0cc7ec', 'name': u'vdd'}, {'ioTune': {'write_bytes_sec': 0L, 'total_iops_sec': 0L, 'read_iops_sec': 0L, 'read_bytes_sec': 0L, 'write_iops_sec': 0L, 'total_bytes_sec': 0L}, 'path': u'/rhev/data-center/94ed7a19-fade-4bd6-83f2-2cbb2f730b95/47202573-6e83-42fd-a274-d11f05eca2dd/images/f8ebfb39-2ac6-4b87-b193-4204d1854edc/50734551-4291-43ca-9e67-a75c0016001a', 'name': u'vde'}, {'ioTune': {'write_bytes_sec': 0L, 'total_iops_sec': 0L, 'read_iops_sec': 0L, 'read_bytes_sec': 0L, 'write_iops_sec': 0L, 'total_bytes_sec': 0L}, 'path': u'/rhev/data-center/94ed7a19-fade-4bd6-83f2-2cbb2f730b95/47202573-6e83-42fd-a274-d11f05eca2dd/images/4e708243-97c3-4279-a32a-cb463e5e43a7/b2125f8b-57ff-4f05-9799-8a0a7605082f', 'name': u'vdf'}, {'ioTune': {'write_bytes_sec': 0L, 'total_iops_sec': 0L, 'read_iops_sec': 0L, 'read_bytes_sec': 0L, 'write_iops_sec': 0L, 'total_bytes_sec': 0L}, 'path': u'/rhev/data-center/94ed7a19-fade-4bd6-83f2-2cbb2f730b95/47202573-6e83-42fd-a274-d11f05eca2dd/images/7e3906ad-7c6b-471d-8589-4cc74ba81b1f/a00c9df0-8800-4aab-b6b0-a6e42f2f155f', 'name': u'vdg'}, {'ioTune': {'write_bytes_sec': 0L, 'total_iops_sec': 0L, 'read_iops_sec': 0L, 'read_bytes_sec': 0L, 'write_iops_sec': 0L, 'total_bytes_sec': 0L}, 'path': u'/rhev/data-center/94ed7a19-fade-4bd6-83f2-2cbb2f730b95/47202573-6e83-42fd-a274-d11f05eca2dd/images/4d00064a-ee20-4f3c-aa48-9cd303af7d8d/73901c65-1eff-492a-94f2-03bd688f5aa8', 'name': u'vdh'}], 'status': {'message': 'Done', 'code': 0}} Thread-15824368::INFO::2016-09-15 11:17:32,079::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:46345 stopped Thread-12785657::DEBUG::2016-09-15 11:17:32,388::monitor::314::Storage.Monitor::(_refreshDomain) Refreshing domain c86d8409-4dd6-4e30-86dc-b5175a7ceb86 Thread-15824369::DEBUG::2016-09-15 11:17:32,389::__init__::318::IOProcessClient::(_run) Starting IOProcess... Thread-15824370::DEBUG::2016-09-15 11:17:32,434::__init__::318::IOProcessClient::(_run) Starting IOProcess... Thread-15824371::DEBUG::2016-09-15 11:17:32,480::__init__::318::IOProcessClient::(_run) Starting IOProcess... Thread-15824372::DEBUG::2016-09-15 11:17:32,524::__init__::318::IOProcessClient::(_run) Starting IOProcess... Thread-15824373::DEBUG::2016-09-15 11:17:32,569::__init__::318::IOProcessClient::(_run) Starting IOProcess... Thread-12785657::DEBUG::2016-09-15 11:17:32,619::fileSD::157::Storage.StorageDomainManifest::(__init__) Reading domain in path /rhev/data-center/mnt/10.10.30.254:_var_nas4_OVirtIB/c86d8409-4dd6-4e30-86dc-b5175a7ceb86 Thread-15824374::DEBUG::2016-09-15 11:17:32,620::__init__::318::IOProcessClient::(_run) Starting IOProcess... Thread-12785657::DEBUG::2016-09-15 11:17:32,664::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with FileMetadataRW backend Thread-12785657::DEBUG::2016-09-15 11:17:32,668::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=colnas04_IB', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=6', 'POOL_DESCRIPTION=Collogia', 'POOL_DOMAINS=272ec473-6041-42ee-bd1a-732789dd18d4:Active,bff3a2be-fdd9-4e37-b416-fa4ef7fafba2:Attached,2c51d320-88ce-4f23-8215-e15f55f66906:Active,63041fa9-e093-4b44-b36f-f39f16d3974f:Attached,c86d8409-4dd6-4e30-86dc-b5175a7ceb86:Active', 'POOL_SPM_ID=4', 'POOL_SPM_LVER=22', 'POOL_UUID=94ed7a19-fade-4bd6-83f2-2cbb2f730b95', 'REMOTE_PATH=10.10.30.254:/var/nas4/OVirtIB', 'ROLE=Regular', 'SDUUID=c86d8409-4dd6-4e30-86dc-b5175a7ceb86', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=fd5b4f561473d4842d797c9d5ff8e3ba189f1bfc'] Thread-12785657::DEBUG::2016-09-15 11:17:32,669::fileSD::671::Storage.StorageDomain::(imageGarbageCollector) Removing remnants of deleted images [] Thread-12785657::INFO::2016-09-15 11:17:32,669::sd::442::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace c86d8409-4dd6-4e30-86dc-b5175a7ceb86_imageNS already registered Thread-12785657::INFO::2016-09-15 11:17:32,669::sd::450::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace c86d8409-4dd6-4e30-86dc-b5175a7ceb86_volumeNS already registered Thread-12785657::DEBUG::2016-09-15 11:17:32,670::fileSD::173::Storage.Misc.excCmd::(getReadDelay) /usr/bin/taskset --cpu-list 0-31 /usr/bin/dd if=/rhev/data-center/mnt/10.10.30.254:_var_nas4_OVirtIB/c86d8409-4dd6-4e30-86dc-b5175a7ceb86/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None) Thread-12785657::DEBUG::2016-09-15 11:17:32,716::fileSD::173::Storage.Misc.excCmd::(getReadDelay) SUCCESS: = '0+1 records in\n0+1 records out\n650 bytes (650 B) copied, 0.000352086 s, 1.8 MB/s\n'; = 0 vdsm.Scheduler::DEBUG::2016-09-15 11:17:32,833::executor::216::Executor::(_discard) Worker discarded: discarded at 0x7eff500ea710> vdsm.Scheduler::DEBUG::2016-09-15 11:17:32,834::executor::161::Executor::(__init__) Starting worker periodic/591484 vdsm.Scheduler::DEBUG::2016-09-15 11:17:32,834::executor::116::Executor::(_worker_discarded) executor state: count=5 workers=set([, , discarded at 0x7eff500ea710>, , ]) periodic/591484::DEBUG::2016-09-15 11:17:32,834::executor::176::Executor::(_run) Worker started Thread-12785646::DEBUG::2016-09-15 11:17:33,435::fileSD::173::Storage.Misc.excCmd::(getReadDelay) /usr/bin/taskset --cpu-list 0-31 /usr/bin/dd if=/rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/47202573-6e83-42fd-a274-d11f05eca2dd/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None) Thread-12785646::DEBUG::2016-09-15 11:17:33,480::fileSD::173::Storage.Misc.excCmd::(getReadDelay) SUCCESS: = '0+1 records in\n0+1 records out\n339 bytes (339 B) copied, 0.000366031 s, 926 kB/s\n'; = 0 jsonrpc.Executor/0::DEBUG::2016-09-15 11:17:35,423::__init__::503::jsonrpc.JsonRpcServer::(_serveRequest) Calling 'VM.merge' in bridge with {u'topVolUUID': u'3d9b0244-fe0a-46dc-936d-4485166f821d', u'vmID': u'26afde81-07e2-46df-b118-8c72cb876227', u'drive': {u'domainID': u'47202573-6e83-42fd-a274-d11f05eca2dd', u'volumeID': u'3d9b0244-fe0a-46dc-936d-4485166f821d', u'poolID': u'94ed7a19-fade-4bd6-83f2-2cbb2f730b95', u'imageID': u'125baba5-2bb1-443a-b457-bf74687481f5'}, u'bandwidth': u'0', u'jobUUID': u'80f60e04-7283-4179-983c-cea1e607afb9', u'baseVolUUID': u'2d6c7d31-2bdb-49db-bf1b-9a9678534179'} jsonrpc.Executor/0::DEBUG::2016-09-15 11:17:35,455::task::595::Storage.TaskManager.Task::(_updateState) Task=`bf54592b-8fdc-45ff-a07f-2d6bf11f8499`::moving from state init -> state preparing jsonrpc.Executor/0::INFO::2016-09-15 11:17:35,455::logUtils::48::dispatcher::(wrapper) Run and protect: getVolumeInfo(sdUUID=u'47202573-6e83-42fd-a274-d11f05eca2dd', spUUID=u'94ed7a19-fade-4bd6-83f2-2cbb2f730b95', imgUUID=u'125baba5-2bb1-443a-b457-bf74687481f5', volUUID=u'2d6c7d31-2bdb-49db-bf1b-9a9678534179', options=None) jsonrpc.Executor/0::DEBUG::2016-09-15 11:17:35,456::resourceManager::199::Storage.ResourceManager.Request::(__init__) ResName=`Storage.47202573-6e83-42fd-a274-d11f05eca2dd`ReqID=`ba9353c9-a524-40c5-9b79-0144c9630480`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3159' at 'getVolumeInfo' jsonrpc.Executor/0::DEBUG::2016-09-15 11:17:35,456::resourceManager::545::Storage.ResourceManager::(registerResource) Trying to register resource 'Storage.47202573-6e83-42fd-a274-d11f05eca2dd' for lock type 'shared' jsonrpc.Executor/0::DEBUG::2016-09-15 11:17:35,456::resourceManager::604::Storage.ResourceManager::(registerResource) Resource 'Storage.47202573-6e83-42fd-a274-d11f05eca2dd' is free. Now locking as 'shared' (1 active user) jsonrpc.Executor/0::DEBUG::2016-09-15 11:17:35,456::resourceManager::239::Storage.ResourceManager.Request::(grant) ResName=`Storage.47202573-6e83-42fd-a274-d11f05eca2dd`ReqID=`ba9353c9-a524-40c5-9b79-0144c9630480`::Granted request jsonrpc.Executor/0::DEBUG::2016-09-15 11:17:35,456::task::827::Storage.TaskManager.Task::(resourceAcquired) Task=`bf54592b-8fdc-45ff-a07f-2d6bf11f8499`::_resourcesAcquired: Storage.47202573-6e83-42fd-a274-d11f05eca2dd (shared) jsonrpc.Executor/0::DEBUG::2016-09-15 11:17:35,457::task::993::Storage.TaskManager.Task::(_decref) Task=`bf54592b-8fdc-45ff-a07f-2d6bf11f8499`::ref 1 aborting False jsonrpc.Executor/0::DEBUG::2016-09-15 11:17:35,458::fileVolume::535::Storage.Volume::(validateVolumePath) validate path for 2d6c7d31-2bdb-49db-bf1b-9a9678534179 jsonrpc.Executor/0::INFO::2016-09-15 11:17:35,459::volume::909::Storage.Volume::(getInfo) Info request: sdUUID=47202573-6e83-42fd-a274-d11f05eca2dd imgUUID=125baba5-2bb1-443a-b457-bf74687481f5 volUUID = 2d6c7d31-2bdb-49db-bf1b-9a9678534179 jsonrpc.Executor/0::INFO::2016-09-15 11:17:35,483::volume::937::Storage.Volume::(getInfo) 47202573-6e83-42fd-a274-d11f05eca2dd/125baba5-2bb1-443a-b457-bf74687481f5/2d6c7d31-2bdb-49db-bf1b-9a9678534179 info is {'status': 'OK', 'domain': '47202573-6e83-42fd-a274-d11f05eca2dd', 'voltype': 'INTERNAL', 'description': '{"DiskAlias":"colzks01_Disk1","DiskDescription":"System"}', 'parent': '00000000-0000-0000-0000-000000000000', 'format': 'RAW', 'image': '125baba5-2bb1-443a-b457-bf74687481f5', 'ctime': '1471417102', 'disktype': '2', 'legality': 'LEGAL', 'mtime': '0', 'apparentsize': '42949672960', 'children': [], 'pool': '', 'capacity': '42949672960', 'uuid': u'2d6c7d31-2bdb-49db-bf1b-9a9678534179', 'truesize': '34659098624', 'type': 'PREALLOCATED'} jsonrpc.Executor/0::INFO::2016-09-15 11:17:35,483::logUtils::51::dispatcher::(wrapper) Run and protect: getVolumeInfo, Return response: {'info': {'status': 'OK', 'domain': '47202573-6e83-42fd-a274-d11f05eca2dd', 'voltype': 'INTERNAL', 'description': '{"DiskAlias":"colzks01_Disk1","DiskDescription":"System"}', 'parent': '00000000-0000-0000-0000-000000000000', 'format': 'RAW', 'image': '125baba5-2bb1-443a-b457-bf74687481f5', 'ctime': '1471417102', 'disktype': '2', 'legality': 'LEGAL', 'mtime': '0', 'apparentsize': '42949672960', 'children': [], 'pool': '', 'capacity': '42949672960', 'uuid': u'2d6c7d31-2bdb-49db-bf1b-9a9678534179', 'truesize': '34659098624', 'type': 'PREALLOCATED'}} jsonrpc.Executor/0::DEBUG::2016-09-15 11:17:35,483::task::1191::Storage.TaskManager.Task::(prepare) Task=`bf54592b-8fdc-45ff-a07f-2d6bf11f8499`::finished: {'info': {'status': 'OK', 'domain': '47202573-6e83-42fd-a274-d11f05eca2dd', 'voltype': 'INTERNAL', 'description': '{"DiskAlias":"colzks01_Disk1","DiskDescription":"System"}', 'parent': '00000000-0000-0000-0000-000000000000', 'format': 'RAW', 'image': '125baba5-2bb1-443a-b457-bf74687481f5', 'ctime': '1471417102', 'disktype': '2', 'legality': 'LEGAL', 'mtime': '0', 'apparentsize': '42949672960', 'children': [], 'pool': '', 'capacity': '42949672960', 'uuid': u'2d6c7d31-2bdb-49db-bf1b-9a9678534179', 'truesize': '34659098624', 'type': 'PREALLOCATED'}} jsonrpc.Executor/0::DEBUG::2016-09-15 11:17:35,483::task::595::Storage.TaskManager.Task::(_updateState) Task=`bf54592b-8fdc-45ff-a07f-2d6bf11f8499`::moving from state preparing -> state finished jsonrpc.Executor/0::DEBUG::2016-09-15 11:17:35,483::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {u'Storage.47202573-6e83-42fd-a274-d11f05eca2dd': < ResourceRef 'Storage.47202573-6e83-42fd-a274-d11f05eca2dd', isValid: 'True' obj: 'None'>} jsonrpc.Executor/0::DEBUG::2016-09-15 11:17:35,483::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} jsonrpc.Executor/0::DEBUG::2016-09-15 11:17:35,484::resourceManager::619::Storage.ResourceManager::(releaseResource) Trying to release resource 'Storage.47202573-6e83-42fd-a274-d11f05eca2dd' jsonrpc.Executor/0::DEBUG::2016-09-15 11:17:35,484::resourceManager::638::Storage.ResourceManager::(releaseResource) Released resource 'Storage.47202573-6e83-42fd-a274-d11f05eca2dd' (0 active users) jsonrpc.Executor/0::DEBUG::2016-09-15 11:17:35,484::resourceManager::644::Storage.ResourceManager::(releaseResource) Resource 'Storage.47202573-6e83-42fd-a274-d11f05eca2dd' is free, finding out if anyone is waiting for it. jsonrpc.Executor/0::DEBUG::2016-09-15 11:17:35,484::resourceManager::652::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'Storage.47202573-6e83-42fd-a274-d11f05eca2dd', Clearing records. jsonrpc.Executor/0::DEBUG::2016-09-15 11:17:35,484::task::993::Storage.TaskManager.Task::(_decref) Task=`bf54592b-8fdc-45ff-a07f-2d6bf11f8499`::ref 0 aborting False jsonrpc.Executor/0::DEBUG::2016-09-15 11:17:35,485::task::595::Storage.TaskManager.Task::(_updateState) Task=`03710361-9abe-4166-bd1f-f63bb32c48f3`::moving from state init -> state preparing jsonrpc.Executor/0::INFO::2016-09-15 11:17:35,485::logUtils::48::dispatcher::(wrapper) Run and protect: getVolumeInfo(sdUUID=u'47202573-6e83-42fd-a274-d11f05eca2dd', spUUID=u'94ed7a19-fade-4bd6-83f2-2cbb2f730b95', imgUUID=u'125baba5-2bb1-443a-b457-bf74687481f5', volUUID=u'3d9b0244-fe0a-46dc-936d-4485166f821d', options=None) jsonrpc.Executor/0::DEBUG::2016-09-15 11:17:35,485::resourceManager::199::Storage.ResourceManager.Request::(__init__) ResName=`Storage.47202573-6e83-42fd-a274-d11f05eca2dd`ReqID=`eb8351bc-fa30-47fa-a0b4-f9e9d214b38e`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3159' at 'getVolumeInfo' jsonrpc.Executor/0::DEBUG::2016-09-15 11:17:35,485::resourceManager::545::Storage.ResourceManager::(registerResource) Trying to register resource 'Storage.47202573-6e83-42fd-a274-d11f05eca2dd' for lock type 'shared' jsonrpc.Executor/0::DEBUG::2016-09-15 11:17:35,486::resourceManager::604::Storage.ResourceManager::(registerResource) Resource 'Storage.47202573-6e83-42fd-a274-d11f05eca2dd' is free. Now locking as 'shared' (1 active user) jsonrpc.Executor/0::DEBUG::2016-09-15 11:17:35,486::resourceManager::239::Storage.ResourceManager.Request::(grant) ResName=`Storage.47202573-6e83-42fd-a274-d11f05eca2dd`ReqID=`eb8351bc-fa30-47fa-a0b4-f9e9d214b38e`::Granted request jsonrpc.Executor/0::DEBUG::2016-09-15 11:17:35,486::task::827::Storage.TaskManager.Task::(resourceAcquired) Task=`03710361-9abe-4166-bd1f-f63bb32c48f3`::_resourcesAcquired: Storage.47202573-6e83-42fd-a274-d11f05eca2dd (shared) jsonrpc.Executor/0::DEBUG::2016-09-15 11:17:35,486::task::993::Storage.TaskManager.Task::(_decref) Task=`03710361-9abe-4166-bd1f-f63bb32c48f3`::ref 1 aborting False jsonrpc.Executor/0::DEBUG::2016-09-15 11:17:35,487::fileVolume::535::Storage.Volume::(validateVolumePath) validate path for 3d9b0244-fe0a-46dc-936d-4485166f821d jsonrpc.Executor/0::INFO::2016-09-15 11:17:35,488::volume::909::Storage.Volume::(getInfo) Info request: sdUUID=47202573-6e83-42fd-a274-d11f05eca2dd imgUUID=125baba5-2bb1-443a-b457-bf74687481f5 volUUID = 3d9b0244-fe0a-46dc-936d-4485166f821d jsonrpc.Executor/0::INFO::2016-09-15 11:17:35,508::volume::937::Storage.Volume::(getInfo) 47202573-6e83-42fd-a274-d11f05eca2dd/125baba5-2bb1-443a-b457-bf74687481f5/3d9b0244-fe0a-46dc-936d-4485166f821d info is {'status': 'OK', 'domain': '47202573-6e83-42fd-a274-d11f05eca2dd', 'voltype': 'LEAF', 'description': '', 'parent': '2d6c7d31-2bdb-49db-bf1b-9a9678534179', 'format': 'COW', 'image': '125baba5-2bb1-443a-b457-bf74687481f5', 'ctime': '1471417102', 'disktype': '2', 'legality': 'LEGAL', 'mtime': '0', 'apparentsize': '10581901312', 'children': [], 'pool': '', 'capacity': '42949672960', 'uuid': u'3d9b0244-fe0a-46dc-936d-4485166f821d', 'truesize': '10582777856', 'type': 'SPARSE'} jsonrpc.Executor/0::INFO::2016-09-15 11:17:35,508::logUtils::51::dispatcher::(wrapper) Run and protect: getVolumeInfo, Return response: {'info': {'status': 'OK', 'domain': '47202573-6e83-42fd-a274-d11f05eca2dd', 'voltype': 'LEAF', 'description': '', 'parent': '2d6c7d31-2bdb-49db-bf1b-9a9678534179', 'format': 'COW', 'image': '125baba5-2bb1-443a-b457-bf74687481f5', 'ctime': '1471417102', 'disktype': '2', 'legality': 'LEGAL', 'mtime': '0', 'apparentsize': '10581901312', 'children': [], 'pool': '', 'capacity': '42949672960', 'uuid': u'3d9b0244-fe0a-46dc-936d-4485166f821d', 'truesize': '10582777856', 'type': 'SPARSE'}} jsonrpc.Executor/0::DEBUG::2016-09-15 11:17:35,508::task::1191::Storage.TaskManager.Task::(prepare) Task=`03710361-9abe-4166-bd1f-f63bb32c48f3`::finished: {'info': {'status': 'OK', 'domain': '47202573-6e83-42fd-a274-d11f05eca2dd', 'voltype': 'LEAF', 'description': '', 'parent': '2d6c7d31-2bdb-49db-bf1b-9a9678534179', 'format': 'COW', 'image': '125baba5-2bb1-443a-b457-bf74687481f5', 'ctime': '1471417102', 'disktype': '2', 'legality': 'LEGAL', 'mtime': '0', 'apparentsize': '10581901312', 'children': [], 'pool': '', 'capacity': '42949672960', 'uuid': u'3d9b0244-fe0a-46dc-936d-4485166f821d', 'truesize': '10582777856', 'type': 'SPARSE'}} jsonrpc.Executor/0::DEBUG::2016-09-15 11:17:35,508::task::595::Storage.TaskManager.Task::(_updateState) Task=`03710361-9abe-4166-bd1f-f63bb32c48f3`::moving from state preparing -> state finished jsonrpc.Executor/0::DEBUG::2016-09-15 11:17:35,508::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {u'Storage.47202573-6e83-42fd-a274-d11f05eca2dd': < ResourceRef 'Storage.47202573-6e83-42fd-a274-d11f05eca2dd', isValid: 'True' obj: 'None'>} jsonrpc.Executor/0::DEBUG::2016-09-15 11:17:35,509::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} jsonrpc.Executor/0::DEBUG::2016-09-15 11:17:35,509::resourceManager::619::Storage.ResourceManager::(releaseResource) Trying to release resource 'Storage.47202573-6e83-42fd-a274-d11f05eca2dd' jsonrpc.Executor/0::DEBUG::2016-09-15 11:17:35,509::resourceManager::638::Storage.ResourceManager::(releaseResource) Released resource 'Storage.47202573-6e83-42fd-a274-d11f05eca2dd' (0 active users) jsonrpc.Executor/0::DEBUG::2016-09-15 11:17:35,509::resourceManager::644::Storage.ResourceManager::(releaseResource) Resource 'Storage.47202573-6e83-42fd-a274-d11f05eca2dd' is free, finding out if anyone is waiting for it. jsonrpc.Executor/0::DEBUG::2016-09-15 11:17:35,509::resourceManager::652::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'Storage.47202573-6e83-42fd-a274-d11f05eca2dd', Clearing records. jsonrpc.Executor/0::DEBUG::2016-09-15 11:17:35,509::task::993::Storage.TaskManager.Task::(_decref) Task=`03710361-9abe-4166-bd1f-f63bb32c48f3`::ref 0 aborting False jsonrpc.Executor/0::INFO::2016-09-15 11:17:35,527::vm::4947::virt.vm::(merge) vmId=`26afde81-07e2-46df-b118-8c72cb876227`::Starting merge with jobUUID='80f60e04-7283-4179-983c-cea1e607afb9' jsonrpc.Executor/4::DEBUG::2016-09-15 11:17:35,531::__init__::503::jsonrpc.JsonRpcServer::(_serveRequest) Calling 'VM.merge' in bridge with {u'topVolUUID': u'2f974f55-842c-492b-8c04-8ed0a8ebaf93', u'vmID': u'26afde81-07e2-46df-b118-8c72cb876227', u'drive': {u'domainID': u'47202573-6e83-42fd-a274-d11f05eca2dd', u'volumeID': u'2f974f55-842c-492b-8c04-8ed0a8ebaf93', u'poolID': u'94ed7a19-fade-4bd6-83f2-2cbb2f730b95', u'imageID': u'c471fa5b-4591-425a-bc33-c8644a0fd12c'}, u'bandwidth': u'0', u'jobUUID': u'70b18d0c-0e0d-477c-83a0-56b225989af9', u'baseVolUUID': u'e7c661e3-f055-4702-ab4d-ec513a1c2b20'} jsonrpc.Executor/4::DEBUG::2016-09-15 11:17:35,561::task::595::Storage.TaskManager.Task::(_updateState) Task=`6892864c-9fb0-43e0-adf2-9eb0a3354764`::moving from state init -> state preparing jsonrpc.Executor/4::INFO::2016-09-15 11:17:35,561::logUtils::48::dispatcher::(wrapper) Run and protect: getVolumeInfo(sdUUID=u'47202573-6e83-42fd-a274-d11f05eca2dd', spUUID=u'94ed7a19-fade-4bd6-83f2-2cbb2f730b95', imgUUID=u'c471fa5b-4591-425a-bc33-c8644a0fd12c', volUUID=u'e7c661e3-f055-4702-ab4d-ec513a1c2b20', options=None) jsonrpc.Executor/4::DEBUG::2016-09-15 11:17:35,561::resourceManager::199::Storage.ResourceManager.Request::(__init__) ResName=`Storage.47202573-6e83-42fd-a274-d11f05eca2dd`ReqID=`6bf6b4da-19db-409f-9efb-e19954f0f15b`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3159' at 'getVolumeInfo' jsonrpc.Executor/4::DEBUG::2016-09-15 11:17:35,561::resourceManager::545::Storage.ResourceManager::(registerResource) Trying to register resource 'Storage.47202573-6e83-42fd-a274-d11f05eca2dd' for lock type 'shared' jsonrpc.Executor/4::DEBUG::2016-09-15 11:17:35,562::resourceManager::604::Storage.ResourceManager::(registerResource) Resource 'Storage.47202573-6e83-42fd-a274-d11f05eca2dd' is free. Now locking as 'shared' (1 active user) jsonrpc.Executor/4::DEBUG::2016-09-15 11:17:35,562::resourceManager::239::Storage.ResourceManager.Request::(grant) ResName=`Storage.47202573-6e83-42fd-a274-d11f05eca2dd`ReqID=`6bf6b4da-19db-409f-9efb-e19954f0f15b`::Granted request jsonrpc.Executor/4::DEBUG::2016-09-15 11:17:35,562::task::827::Storage.TaskManager.Task::(resourceAcquired) Task=`6892864c-9fb0-43e0-adf2-9eb0a3354764`::_resourcesAcquired: Storage.47202573-6e83-42fd-a274-d11f05eca2dd (shared) jsonrpc.Executor/4::DEBUG::2016-09-15 11:17:35,562::task::993::Storage.TaskManager.Task::(_decref) Task=`6892864c-9fb0-43e0-adf2-9eb0a3354764`::ref 1 aborting False jsonrpc.Executor/4::DEBUG::2016-09-15 11:17:35,564::fileVolume::535::Storage.Volume::(validateVolumePath) validate path for e7c661e3-f055-4702-ab4d-ec513a1c2b20 jsonrpc.Executor/4::INFO::2016-09-15 11:17:35,565::volume::909::Storage.Volume::(getInfo) Info request: sdUUID=47202573-6e83-42fd-a274-d11f05eca2dd imgUUID=c471fa5b-4591-425a-bc33-c8644a0fd12c volUUID = e7c661e3-f055-4702-ab4d-ec513a1c2b20 jsonrpc.Executor/4::INFO::2016-09-15 11:17:35,572::volume::937::Storage.Volume::(getInfo) 47202573-6e83-42fd-a274-d11f05eca2dd/c471fa5b-4591-425a-bc33-c8644a0fd12c/e7c661e3-f055-4702-ab4d-ec513a1c2b20 info is {'status': 'OK', 'domain': '47202573-6e83-42fd-a274-d11f05eca2dd', 'voltype': 'INTERNAL', 'description': '{"DiskAlias":"colzks01_Disk2","DiskDescription":"Backup"}', 'parent': '00000000-0000-0000-0000-000000000000', 'format': 'RAW', 'image': 'c471fa5b-4591-425a-bc33-c8644a0fd12c', 'ctime': '1471417103', 'disktype': '2', 'legality': 'LEGAL', 'mtime': '0', 'apparentsize': '21474836480', 'children': [], 'pool': '', 'capacity': '21474836480', 'uuid': u'e7c661e3-f055-4702-ab4d-ec513a1c2b20', 'truesize': '1378996224', 'type': 'SPARSE'} jsonrpc.Executor/4::INFO::2016-09-15 11:17:35,572::logUtils::51::dispatcher::(wrapper) Run and protect: getVolumeInfo, Return response: {'info': {'status': 'OK', 'domain': '47202573-6e83-42fd-a274-d11f05eca2dd', 'voltype': 'INTERNAL', 'description': '{"DiskAlias":"colzks01_Disk2","DiskDescription":"Backup"}', 'parent': '00000000-0000-0000-0000-000000000000', 'format': 'RAW', 'image': 'c471fa5b-4591-425a-bc33-c8644a0fd12c', 'ctime': '1471417103', 'disktype': '2', 'legality': 'LEGAL', 'mtime': '0', 'apparentsize': '21474836480', 'children': [], 'pool': '', 'capacity': '21474836480', 'uuid': u'e7c661e3-f055-4702-ab4d-ec513a1c2b20', 'truesize': '1378996224', 'type': 'SPARSE'}} jsonrpc.Executor/4::DEBUG::2016-09-15 11:17:35,572::task::1191::Storage.TaskManager.Task::(prepare) Task=`6892864c-9fb0-43e0-adf2-9eb0a3354764`::finished: {'info': {'status': 'OK', 'domain': '47202573-6e83-42fd-a274-d11f05eca2dd', 'voltype': 'INTERNAL', 'description': '{"DiskAlias":"colzks01_Disk2","DiskDescription":"Backup"}', 'parent': '00000000-0000-0000-0000-000000000000', 'format': 'RAW', 'image': 'c471fa5b-4591-425a-bc33-c8644a0fd12c', 'ctime': '1471417103', 'disktype': '2', 'legality': 'LEGAL', 'mtime': '0', 'apparentsize': '21474836480', 'children': [], 'pool': '', 'capacity': '21474836480', 'uuid': u'e7c661e3-f055-4702-ab4d-ec513a1c2b20', 'truesize': '1378996224', 'type': 'SPARSE'}} jsonrpc.Executor/4::DEBUG::2016-09-15 11:17:35,572::task::595::Storage.TaskManager.Task::(_updateState) Task=`6892864c-9fb0-43e0-adf2-9eb0a3354764`::moving from state preparing -> state finished jsonrpc.Executor/4::DEBUG::2016-09-15 11:17:35,573::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {u'Storage.47202573-6e83-42fd-a274-d11f05eca2dd': < ResourceRef 'Storage.47202573-6e83-42fd-a274-d11f05eca2dd', isValid: 'True' obj: 'None'>} jsonrpc.Executor/4::DEBUG::2016-09-15 11:17:35,573::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} jsonrpc.Executor/4::DEBUG::2016-09-15 11:17:35,573::resourceManager::619::Storage.ResourceManager::(releaseResource) Trying to release resource 'Storage.47202573-6e83-42fd-a274-d11f05eca2dd' jsonrpc.Executor/4::DEBUG::2016-09-15 11:17:35,573::resourceManager::638::Storage.ResourceManager::(releaseResource) Released resource 'Storage.47202573-6e83-42fd-a274-d11f05eca2dd' (0 active users) jsonrpc.Executor/4::DEBUG::2016-09-15 11:17:35,573::resourceManager::644::Storage.ResourceManager::(releaseResource) Resource 'Storage.47202573-6e83-42fd-a274-d11f05eca2dd' is free, finding out if anyone is waiting for it. jsonrpc.Executor/4::DEBUG::2016-09-15 11:17:35,573::resourceManager::652::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'Storage.47202573-6e83-42fd-a274-d11f05eca2dd', Clearing records. jsonrpc.Executor/4::DEBUG::2016-09-15 11:17:35,573::task::993::Storage.TaskManager.Task::(_decref) Task=`6892864c-9fb0-43e0-adf2-9eb0a3354764`::ref 0 aborting False jsonrpc.Executor/4::DEBUG::2016-09-15 11:17:35,574::task::595::Storage.TaskManager.Task::(_updateState) Task=`19fd74ea-2e18-46d4-8155-4113ca3b847a`::moving from state init -> state preparing jsonrpc.Executor/4::INFO::2016-09-15 11:17:35,574::logUtils::48::dispatcher::(wrapper) Run and protect: getVolumeInfo(sdUUID=u'47202573-6e83-42fd-a274-d11f05eca2dd', spUUID=u'94ed7a19-fade-4bd6-83f2-2cbb2f730b95', imgUUID=u'c471fa5b-4591-425a-bc33-c8644a0fd12c', volUUID=u'2f974f55-842c-492b-8c04-8ed0a8ebaf93', options=None) jsonrpc.Executor/4::DEBUG::2016-09-15 11:17:35,574::resourceManager::199::Storage.ResourceManager.Request::(__init__) ResName=`Storage.47202573-6e83-42fd-a274-d11f05eca2dd`ReqID=`d24f3644-5bab-43ff-9bd4-db6ed65b0601`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3159' at 'getVolumeInfo' jsonrpc.Executor/4::DEBUG::2016-09-15 11:17:35,574::resourceManager::545::Storage.ResourceManager::(registerResource) Trying to register resource 'Storage.47202573-6e83-42fd-a274-d11f05eca2dd' for lock type 'shared' jsonrpc.Executor/4::DEBUG::2016-09-15 11:17:35,575::resourceManager::604::Storage.ResourceManager::(registerResource) Resource 'Storage.47202573-6e83-42fd-a274-d11f05eca2dd' is free. Now locking as 'shared' (1 active user) jsonrpc.Executor/4::DEBUG::2016-09-15 11:17:35,575::resourceManager::239::Storage.ResourceManager.Request::(grant) ResName=`Storage.47202573-6e83-42fd-a274-d11f05eca2dd`ReqID=`d24f3644-5bab-43ff-9bd4-db6ed65b0601`::Granted request jsonrpc.Executor/4::DEBUG::2016-09-15 11:17:35,575::task::827::Storage.TaskManager.Task::(resourceAcquired) Task=`19fd74ea-2e18-46d4-8155-4113ca3b847a`::_resourcesAcquired: Storage.47202573-6e83-42fd-a274-d11f05eca2dd (shared) jsonrpc.Executor/4::DEBUG::2016-09-15 11:17:35,575::task::993::Storage.TaskManager.Task::(_decref) Task=`19fd74ea-2e18-46d4-8155-4113ca3b847a`::ref 1 aborting False jsonrpc.Executor/4::DEBUG::2016-09-15 11:17:35,576::fileVolume::535::Storage.Volume::(validateVolumePath) validate path for 2f974f55-842c-492b-8c04-8ed0a8ebaf93 jsonrpc.Executor/4::INFO::2016-09-15 11:17:35,577::volume::909::Storage.Volume::(getInfo) Info request: sdUUID=47202573-6e83-42fd-a274-d11f05eca2dd imgUUID=c471fa5b-4591-425a-bc33-c8644a0fd12c volUUID = 2f974f55-842c-492b-8c04-8ed0a8ebaf93 jsonrpc.Executor/4::INFO::2016-09-15 11:17:35,601::volume::937::Storage.Volume::(getInfo) 47202573-6e83-42fd-a274-d11f05eca2dd/c471fa5b-4591-425a-bc33-c8644a0fd12c/2f974f55-842c-492b-8c04-8ed0a8ebaf93 info is {'status': 'OK', 'domain': '47202573-6e83-42fd-a274-d11f05eca2dd', 'voltype': 'LEAF', 'description': '', 'parent': 'e7c661e3-f055-4702-ab4d-ec513a1c2b20', 'format': 'COW', 'image': 'c471fa5b-4591-425a-bc33-c8644a0fd12c', 'ctime': '1471417103', 'disktype': '2', 'legality': 'LEGAL', 'mtime': '0', 'apparentsize': '384958464', 'children': [], 'pool': '', 'capacity': '21474836480', 'uuid': u'2f974f55-842c-492b-8c04-8ed0a8ebaf93', 'truesize': '384995328', 'type': 'SPARSE'} jsonrpc.Executor/4::INFO::2016-09-15 11:17:35,601::logUtils::51::dispatcher::(wrapper) Run and protect: getVolumeInfo, Return response: {'info': {'status': 'OK', 'domain': '47202573-6e83-42fd-a274-d11f05eca2dd', 'voltype': 'LEAF', 'description': '', 'parent': 'e7c661e3-f055-4702-ab4d-ec513a1c2b20', 'format': 'COW', 'image': 'c471fa5b-4591-425a-bc33-c8644a0fd12c', 'ctime': '1471417103', 'disktype': '2', 'legality': 'LEGAL', 'mtime': '0', 'apparentsize': '384958464', 'children': [], 'pool': '', 'capacity': '21474836480', 'uuid': u'2f974f55-842c-492b-8c04-8ed0a8ebaf93', 'truesize': '384995328', 'type': 'SPARSE'}} jsonrpc.Executor/4::DEBUG::2016-09-15 11:17:35,601::task::1191::Storage.TaskManager.Task::(prepare) Task=`19fd74ea-2e18-46d4-8155-4113ca3b847a`::finished: {'info': {'status': 'OK', 'domain': '47202573-6e83-42fd-a274-d11f05eca2dd', 'voltype': 'LEAF', 'description': '', 'parent': 'e7c661e3-f055-4702-ab4d-ec513a1c2b20', 'format': 'COW', 'image': 'c471fa5b-4591-425a-bc33-c8644a0fd12c', 'ctime': '1471417103', 'disktype': '2', 'legality': 'LEGAL', 'mtime': '0', 'apparentsize': '384958464', 'children': [], 'pool': '', 'capacity': '21474836480', 'uuid': u'2f974f55-842c-492b-8c04-8ed0a8ebaf93', 'truesize': '384995328', 'type': 'SPARSE'}} jsonrpc.Executor/4::DEBUG::2016-09-15 11:17:35,601::task::595::Storage.TaskManager.Task::(_updateState) Task=`19fd74ea-2e18-46d4-8155-4113ca3b847a`::moving from state preparing -> state finished jsonrpc.Executor/4::DEBUG::2016-09-15 11:17:35,601::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {u'Storage.47202573-6e83-42fd-a274-d11f05eca2dd': < ResourceRef 'Storage.47202573-6e83-42fd-a274-d11f05eca2dd', isValid: 'True' obj: 'None'>} jsonrpc.Executor/4::DEBUG::2016-09-15 11:17:35,602::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} jsonrpc.Executor/4::DEBUG::2016-09-15 11:17:35,602::resourceManager::619::Storage.ResourceManager::(releaseResource) Trying to release resource 'Storage.47202573-6e83-42fd-a274-d11f05eca2dd' jsonrpc.Executor/4::DEBUG::2016-09-15 11:17:35,602::resourceManager::638::Storage.ResourceManager::(releaseResource) Released resource 'Storage.47202573-6e83-42fd-a274-d11f05eca2dd' (0 active users) jsonrpc.Executor/4::DEBUG::2016-09-15 11:17:35,602::resourceManager::644::Storage.ResourceManager::(releaseResource) Resource 'Storage.47202573-6e83-42fd-a274-d11f05eca2dd' is free, finding out if anyone is waiting for it. jsonrpc.Executor/4::DEBUG::2016-09-15 11:17:35,602::resourceManager::652::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'Storage.47202573-6e83-42fd-a274-d11f05eca2dd', Clearing records. jsonrpc.Executor/4::DEBUG::2016-09-15 11:17:35,602::task::993::Storage.TaskManager.Task::(_decref) Task=`19fd74ea-2e18-46d4-8155-4113ca3b847a`::ref 0 aborting False jsonrpc.Executor/4::INFO::2016-09-15 11:17:35,671::vm::4947::virt.vm::(merge) vmId=`26afde81-07e2-46df-b118-8c72cb876227`::Starting merge with jobUUID='70b18d0c-0e0d-477c-83a0-56b225989af9' Reactor thread::INFO::2016-09-15 11:17:36,318::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:46346 Reactor thread::DEBUG::2016-09-15 11:17:36,325::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11 Reactor thread::INFO::2016-09-15 11:17:36,325::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:46346 Reactor thread::DEBUG::2016-09-15 11:17:36,325::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 46346) BindingXMLRPC::INFO::2016-09-15 11:17:36,326::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:46346 Thread-15824375::INFO::2016-09-15 11:17:36,326::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:46346 started Thread-15824375::INFO::2016-09-15 11:17:36,359::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:46346 stopped Reactor thread::INFO::2016-09-15 11:17:36,360::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:46347 Reactor thread::DEBUG::2016-09-15 11:17:36,366::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11 Reactor thread::INFO::2016-09-15 11:17:36,367::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:46347 Reactor thread::DEBUG::2016-09-15 11:17:36,367::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 46347) BindingXMLRPC::INFO::2016-09-15 11:17:36,367::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:46347 Thread-15824376::INFO::2016-09-15 11:17:36,367::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:46347 started Thread-15824376::DEBUG::2016-09-15 11:17:36,368::bindingxmlrpc::1262::vds::(wrapper) client [127.0.0.1]::call vmGetIoTunePolicy with ('838e4000-e835-48da-a6fb-f6f5ec4a8473',) {} Thread-15824376::DEBUG::2016-09-15 11:17:36,369::bindingxmlrpc::1269::vds::(wrapper) return vmGetIoTunePolicy with {'ioTunePolicy': [], 'status': {'message': 'Done', 'code': 0}} Thread-15824376::INFO::2016-09-15 11:17:36,370::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:46347 stopped Reactor thread::INFO::2016-09-15 11:17:36,371::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:46348 Reactor thread::DEBUG::2016-09-15 11:17:36,377::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11 Reactor thread::INFO::2016-09-15 11:17:36,377::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:46348 Reactor thread::DEBUG::2016-09-15 11:17:36,377::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 46348) BindingXMLRPC::INFO::2016-09-15 11:17:36,378::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:46348 Thread-15824377::INFO::2016-09-15 11:17:36,378::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:46348 started Thread-15824377::DEBUG::2016-09-15 11:17:36,379::bindingxmlrpc::1262::vds::(wrapper) client [127.0.0.1]::call vmGetIoTune with ('838e4000-e835-48da-a6fb-f6f5ec4a8473',) {} Thread-15824378::DEBUG::2016-09-15 11:17:36,508::task::595::Storage.TaskManager.Task::(_updateState) Task=`4cfe0948-b883-4dfa-bc5f-e2a8bfed699c`::moving from state init -> state preparing Thread-15824378::INFO::2016-09-15 11:17:36,508::logUtils::48::dispatcher::(wrapper) Run and protect: getVolumeInfo(sdUUID=u'47202573-6e83-42fd-a274-d11f05eca2dd', spUUID=u'94ed7a19-fade-4bd6-83f2-2cbb2f730b95', imgUUID=u'125baba5-2bb1-443a-b457-bf74687481f5', volUUID=u'3d9b0244-fe0a-46dc-936d-4485166f821d', options=None) Thread-15824378::DEBUG::2016-09-15 11:17:36,508::resourceManager::199::Storage.ResourceManager.Request::(__init__) ResName=`Storage.47202573-6e83-42fd-a274-d11f05eca2dd`ReqID=`66b952c5-3dfe-4896-9d8c-01f433ecbe31`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3159' at 'getVolumeInfo' Thread-15824378::DEBUG::2016-09-15 11:17:36,509::resourceManager::545::Storage.ResourceManager::(registerResource) Trying to register resource 'Storage.47202573-6e83-42fd-a274-d11f05eca2dd' for lock type 'shared' Thread-15824378::DEBUG::2016-09-15 11:17:36,509::resourceManager::604::Storage.ResourceManager::(registerResource) Resource 'Storage.47202573-6e83-42fd-a274-d11f05eca2dd' is free. Now locking as 'shared' (1 active user) jsonrpc.Executor/4::DEBUG::2016-09-15 11:17:36,509::__init__::533::jsonrpc.JsonRpcServer::(_serveRequest) Return 'VM.merge' in bridge with True Thread-15824378::DEBUG::2016-09-15 11:17:36,510::resourceManager::239::Storage.ResourceManager.Request::(grant) ResName=`Storage.47202573-6e83-42fd-a274-d11f05eca2dd`ReqID=`66b952c5-3dfe-4896-9d8c-01f433ecbe31`::Granted request Thread-15824378::DEBUG::2016-09-15 11:17:36,510::task::827::Storage.TaskManager.Task::(resourceAcquired) Task=`4cfe0948-b883-4dfa-bc5f-e2a8bfed699c`::_resourcesAcquired: Storage.47202573-6e83-42fd-a274-d11f05eca2dd (shared) Thread-15824378::DEBUG::2016-09-15 11:17:36,510::task::993::Storage.TaskManager.Task::(_decref) Task=`4cfe0948-b883-4dfa-bc5f-e2a8bfed699c`::ref 1 aborting False jsonrpc.Executor/0::DEBUG::2016-09-15 11:17:36,511::vm::4864::virt.vm::(queryBlockJobs) vmId=`26afde81-07e2-46df-b118-8c72cb876227`::Still waiting for block job 80f60e04-7283-4179-983c-cea1e607afb9 to be synchronized Thread-15824378::DEBUG::2016-09-15 11:17:36,512::fileVolume::535::Storage.Volume::(validateVolumePath) validate path for 3d9b0244-fe0a-46dc-936d-4485166f821d jsonrpc.Executor/0::DEBUG::2016-09-15 11:17:36,513::__init__::533::jsonrpc.JsonRpcServer::(_serveRequest) Return 'VM.merge' in bridge with True Thread-15824378::INFO::2016-09-15 11:17:36,514::volume::909::Storage.Volume::(getInfo) Info request: sdUUID=47202573-6e83-42fd-a274-d11f05eca2dd imgUUID=125baba5-2bb1-443a-b457-bf74687481f5 volUUID = 3d9b0244-fe0a-46dc-936d-4485166f821d Thread-15824378::INFO::2016-09-15 11:17:36,517::volume::937::Storage.Volume::(getInfo) 47202573-6e83-42fd-a274-d11f05eca2dd/125baba5-2bb1-443a-b457-bf74687481f5/3d9b0244-fe0a-46dc-936d-4485166f821d info is {'status': 'OK', 'domain': '47202573-6e83-42fd-a274-d11f05eca2dd', 'voltype': 'LEAF', 'description': '', 'parent': '2d6c7d31-2bdb-49db-bf1b-9a9678534179', 'format': 'COW', 'image': '125baba5-2bb1-443a-b457-bf74687481f5', 'ctime': '1471417102', 'disktype': '2', 'legality': 'LEGAL', 'mtime': '0', 'apparentsize': '10581901312', 'children': [], 'pool': '', 'capacity': '42949672960', 'uuid': u'3d9b0244-fe0a-46dc-936d-4485166f821d', 'truesize': '10582777856', 'type': 'SPARSE'} Thread-15824378::INFO::2016-09-15 11:17:36,517::logUtils::51::dispatcher::(wrapper) Run and protect: getVolumeInfo, Return response: {'info': {'status': 'OK', 'domain': '47202573-6e83-42fd-a274-d11f05eca2dd', 'voltype': 'LEAF', 'description': '', 'parent': '2d6c7d31-2bdb-49db-bf1b-9a9678534179', 'format': 'COW', 'image': '125baba5-2bb1-443a-b457-bf74687481f5', 'ctime': '1471417102', 'disktype': '2', 'legality': 'LEGAL', 'mtime': '0', 'apparentsize': '10581901312', 'children': [], 'pool': '', 'capacity': '42949672960', 'uuid': u'3d9b0244-fe0a-46dc-936d-4485166f821d', 'truesize': '10582777856', 'type': 'SPARSE'}} Thread-15824378::DEBUG::2016-09-15 11:17:36,517::task::1191::Storage.TaskManager.Task::(prepare) Task=`4cfe0948-b883-4dfa-bc5f-e2a8bfed699c`::finished: {'info': {'status': 'OK', 'domain': '47202573-6e83-42fd-a274-d11f05eca2dd', 'voltype': 'LEAF', 'description': '', 'parent': '2d6c7d31-2bdb-49db-bf1b-9a9678534179', 'format': 'COW', 'image': '125baba5-2bb1-443a-b457-bf74687481f5', 'ctime': '1471417102', 'disktype': '2', 'legality': 'LEGAL', 'mtime': '0', 'apparentsize': '10581901312', 'children': [], 'pool': '', 'capacity': '42949672960', 'uuid': u'3d9b0244-fe0a-46dc-936d-4485166f821d', 'truesize': '10582777856', 'type': 'SPARSE'}} Thread-15824378::DEBUG::2016-09-15 11:17:36,517::task::595::Storage.TaskManager.Task::(_updateState) Task=`4cfe0948-b883-4dfa-bc5f-e2a8bfed699c`::moving from state preparing -> state finished Thread-15824378::DEBUG::2016-09-15 11:17:36,517::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {u'Storage.47202573-6e83-42fd-a274-d11f05eca2dd': < ResourceRef 'Storage.47202573-6e83-42fd-a274-d11f05eca2dd', isValid: 'True' obj: 'None'>} Thread-15824378::DEBUG::2016-09-15 11:17:36,518::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-15824378::DEBUG::2016-09-15 11:17:36,518::resourceManager::619::Storage.ResourceManager::(releaseResource) Trying to release resource 'Storage.47202573-6e83-42fd-a274-d11f05eca2dd' Thread-15824378::DEBUG::2016-09-15 11:17:36,518::resourceManager::638::Storage.ResourceManager::(releaseResource) Released resource 'Storage.47202573-6e83-42fd-a274-d11f05eca2dd' (0 active users) Thread-15824378::DEBUG::2016-09-15 11:17:36,518::resourceManager::644::Storage.ResourceManager::(releaseResource) Resource 'Storage.47202573-6e83-42fd-a274-d11f05eca2dd' is free, finding out if anyone is waiting for it. Thread-15824378::DEBUG::2016-09-15 11:17:36,518::resourceManager::652::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'Storage.47202573-6e83-42fd-a274-d11f05eca2dd', Clearing records. Thread-15824378::DEBUG::2016-09-15 11:17:36,518::task::993::Storage.TaskManager.Task::(_decref) Task=`4cfe0948-b883-4dfa-bc5f-e2a8bfed699c`::ref 0 aborting False Thread-15824378::DEBUG::2016-09-15 11:17:36,519::task::595::Storage.TaskManager.Task::(_updateState) Task=`b08d7e38-c6ea-4016-a802-12d4db88108f`::moving from state init -> state preparing Thread-15824378::INFO::2016-09-15 11:17:36,519::logUtils::48::dispatcher::(wrapper) Run and protect: setVolumeSize(sdUUID=u'47202573-6e83-42fd-a274-d11f05eca2dd', spUUID=u'94ed7a19-fade-4bd6-83f2-2cbb2f730b95', imgUUID=u'125baba5-2bb1-443a-b457-bf74687481f5', volUUID=u'2d6c7d31-2bdb-49db-bf1b-9a9678534179', capacity='42949672960') Thread-15824378::DEBUG::2016-09-15 11:17:36,520::fileVolume::535::Storage.Volume::(validateVolumePath) validate path for 2d6c7d31-2bdb-49db-bf1b-9a9678534179 Thread-15824378::INFO::2016-09-15 11:17:36,553::logUtils::51::dispatcher::(wrapper) Run and protect: setVolumeSize, Return response: None Thread-15824378::DEBUG::2016-09-15 11:17:36,553::task::1191::Storage.TaskManager.Task::(prepare) Task=`b08d7e38-c6ea-4016-a802-12d4db88108f`::finished: None Thread-15824378::DEBUG::2016-09-15 11:17:36,553::task::595::Storage.TaskManager.Task::(_updateState) Task=`b08d7e38-c6ea-4016-a802-12d4db88108f`::moving from state preparing -> state finished Thread-15824378::DEBUG::2016-09-15 11:17:36,553::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-15824378::DEBUG::2016-09-15 11:17:36,553::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-15824378::DEBUG::2016-09-15 11:17:36,553::task::993::Storage.TaskManager.Task::(_decref) Task=`b08d7e38-c6ea-4016-a802-12d4db88108f`::ref 0 aborting False Thread-15824378::DEBUG::2016-09-15 11:17:36,554::task::595::Storage.TaskManager.Task::(_updateState) Task=`fc6fd5dd-58ad-46ef-9a20-764d5954eb0f`::moving from state init -> state preparing Thread-15824378::INFO::2016-09-15 11:17:36,554::logUtils::48::dispatcher::(wrapper) Run and protect: imageSyncVolumeChain(sdUUID=u'47202573-6e83-42fd-a274-d11f05eca2dd', imgUUID=u'125baba5-2bb1-443a-b457-bf74687481f5', volUUID=u'3d9b0244-fe0a-46dc-936d-4485166f821d', newChain=[u'2d6c7d31-2bdb-49db-bf1b-9a9678534179']) Thread-15824378::DEBUG::2016-09-15 11:17:36,554::resourceManager::199::Storage.ResourceManager.Request::(__init__) ResName=`47202573-6e83-42fd-a274-d11f05eca2dd_imageNS.125baba5-2bb1-443a-b457-bf74687481f5`ReqID=`f28e7189-0173-4b23-8f53-72d72a015cd5`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '1857' at 'imageSyncVolumeChain' Thread-15824378::DEBUG::2016-09-15 11:17:36,554::resourceManager::545::Storage.ResourceManager::(registerResource) Trying to register resource '47202573-6e83-42fd-a274-d11f05eca2dd_imageNS.125baba5-2bb1-443a-b457-bf74687481f5' for lock type 'shared' Thread-15824378::DEBUG::2016-09-15 11:17:36,556::fileVolume::535::Storage.Volume::(validateVolumePath) validate path for 2d6c7d31-2bdb-49db-bf1b-9a9678534179 Thread-15824378::DEBUG::2016-09-15 11:17:36,559::fileVolume::535::Storage.Volume::(validateVolumePath) validate path for 3d9b0244-fe0a-46dc-936d-4485166f821d Thread-15824378::DEBUG::2016-09-15 11:17:36,561::fileVolume::535::Storage.Volume::(validateVolumePath) validate path for 2d6c7d31-2bdb-49db-bf1b-9a9678534179 Thread-15824378::DEBUG::2016-09-15 11:17:36,563::fileVolume::535::Storage.Volume::(validateVolumePath) validate path for 2d6c7d31-2bdb-49db-bf1b-9a9678534179 Thread-15824378::DEBUG::2016-09-15 11:17:36,565::fileVolume::535::Storage.Volume::(validateVolumePath) validate path for 3d9b0244-fe0a-46dc-936d-4485166f821d Thread-15824378::DEBUG::2016-09-15 11:17:36,568::fileVolume::535::Storage.Volume::(validateVolumePath) validate path for 2d6c7d31-2bdb-49db-bf1b-9a9678534179 Thread-15824378::INFO::2016-09-15 11:17:36,570::image::228::Storage.Image::(getChain) sdUUID=47202573-6e83-42fd-a274-d11f05eca2dd imgUUID=125baba5-2bb1-443a-b457-bf74687481f5 chain=[, ] Thread-15824378::DEBUG::2016-09-15 11:17:36,571::resourceManager::199::Storage.ResourceManager.Request::(__init__) ResName=`47202573-6e83-42fd-a274-d11f05eca2dd_volumeNS.2d6c7d31-2bdb-49db-bf1b-9a9678534179`ReqID=`f647d5db-bcad-4cc9-b3a8-0539e80a97e4`::Request was made in '/usr/share/vdsm/storage/resourceFactories.py' line '172' at '__getResourceCandidatesList' Thread-15824378::DEBUG::2016-09-15 11:17:36,572::resourceManager::545::Storage.ResourceManager::(registerResource) Trying to register resource '47202573-6e83-42fd-a274-d11f05eca2dd_volumeNS.2d6c7d31-2bdb-49db-bf1b-9a9678534179' for lock type 'shared' Thread-15824378::DEBUG::2016-09-15 11:17:36,572::resourceManager::604::Storage.ResourceManager::(registerResource) Resource '47202573-6e83-42fd-a274-d11f05eca2dd_volumeNS.2d6c7d31-2bdb-49db-bf1b-9a9678534179' is free. Now locking as 'shared' (1 active user) Thread-15824378::DEBUG::2016-09-15 11:17:36,572::resourceManager::239::Storage.ResourceManager.Request::(grant) ResName=`47202573-6e83-42fd-a274-d11f05eca2dd_volumeNS.2d6c7d31-2bdb-49db-bf1b-9a9678534179`ReqID=`f647d5db-bcad-4cc9-b3a8-0539e80a97e4`::Granted request Thread-15824378::DEBUG::2016-09-15 11:17:36,573::resourceManager::199::Storage.ResourceManager.Request::(__init__) ResName=`47202573-6e83-42fd-a274-d11f05eca2dd_volumeNS.3d9b0244-fe0a-46dc-936d-4485166f821d`ReqID=`a1874837-3f73-4950-bc8e-6bcf8737c0bb`::Request was made in '/usr/share/vdsm/storage/resourceFactories.py' line '172' at '__getResourceCandidatesList' Thread-15824378::DEBUG::2016-09-15 11:17:36,573::resourceManager::545::Storage.ResourceManager::(registerResource) Trying to register resource '47202573-6e83-42fd-a274-d11f05eca2dd_volumeNS.3d9b0244-fe0a-46dc-936d-4485166f821d' for lock type 'shared' Thread-15824378::DEBUG::2016-09-15 11:17:36,573::resourceManager::604::Storage.ResourceManager::(registerResource) Resource '47202573-6e83-42fd-a274-d11f05eca2dd_volumeNS.3d9b0244-fe0a-46dc-936d-4485166f821d' is free. Now locking as 'shared' (1 active user) Thread-15824378::DEBUG::2016-09-15 11:17:36,573::resourceManager::239::Storage.ResourceManager.Request::(grant) ResName=`47202573-6e83-42fd-a274-d11f05eca2dd_volumeNS.3d9b0244-fe0a-46dc-936d-4485166f821d`ReqID=`a1874837-3f73-4950-bc8e-6bcf8737c0bb`::Granted request Thread-15824378::DEBUG::2016-09-15 11:17:36,573::resourceManager::604::Storage.ResourceManager::(registerResource) Resource '47202573-6e83-42fd-a274-d11f05eca2dd_imageNS.125baba5-2bb1-443a-b457-bf74687481f5' is free. Now locking as 'shared' (1 active user) Thread-15824378::DEBUG::2016-09-15 11:17:36,574::resourceManager::239::Storage.ResourceManager.Request::(grant) ResName=`47202573-6e83-42fd-a274-d11f05eca2dd_imageNS.125baba5-2bb1-443a-b457-bf74687481f5`ReqID=`f28e7189-0173-4b23-8f53-72d72a015cd5`::Granted request Thread-15824378::DEBUG::2016-09-15 11:17:36,575::fileVolume::535::Storage.Volume::(validateVolumePath) validate path for 3d9b0244-fe0a-46dc-936d-4485166f821d Thread-15824378::DEBUG::2016-09-15 11:17:36,578::fileVolume::535::Storage.Volume::(validateVolumePath) validate path for 2d6c7d31-2bdb-49db-bf1b-9a9678534179 Thread-15824378::INFO::2016-09-15 11:17:36,580::image::228::Storage.Image::(getChain) sdUUID=47202573-6e83-42fd-a274-d11f05eca2dd imgUUID=125baba5-2bb1-443a-b457-bf74687481f5 chain=[, ] Thread-15824378::DEBUG::2016-09-15 11:17:36,580::image::1172::Storage.Image::(syncVolumeChain) unlinking subchain: [u'3d9b0244-fe0a-46dc-936d-4485166f821d'] Thread-15824378::DEBUG::2016-09-15 11:17:36,581::fileVolume::535::Storage.Volume::(validateVolumePath) validate path for 3d9b0244-fe0a-46dc-936d-4485166f821d Thread-15824378::DEBUG::2016-09-15 11:17:36,583::fileVolume::535::Storage.Volume::(validateVolumePath) validate path for 3d9b0244-fe0a-46dc-936d-4485166f821d Thread-15824378::DEBUG::2016-09-15 11:17:36,584::image::1178::Storage.Image::(syncVolumeChain) Leaf volume is being removed from the chain. Marking it ILLEGAL to prevent data corruption Thread-15824378::INFO::2016-09-15 11:17:36,584::volume::667::Storage.Volume::(setLegality) sdUUID=47202573-6e83-42fd-a274-d11f05eca2dd imgUUID=125baba5-2bb1-443a-b457-bf74687481f5 volUUID = 3d9b0244-fe0a-46dc-936d-4485166f821d legality = ILLEGAL Thread-15824378::DEBUG::2016-09-15 11:17:36,586::resourceManager::619::Storage.ResourceManager::(releaseResource) Trying to release resource '47202573-6e83-42fd-a274-d11f05eca2dd_imageNS.125baba5-2bb1-443a-b457-bf74687481f5' Thread-15824378::DEBUG::2016-09-15 11:17:36,586::resourceManager::638::Storage.ResourceManager::(releaseResource) Released resource '47202573-6e83-42fd-a274-d11f05eca2dd_imageNS.125baba5-2bb1-443a-b457-bf74687481f5' (0 active users) Thread-15824378::DEBUG::2016-09-15 11:17:36,587::resourceManager::644::Storage.ResourceManager::(releaseResource) Resource '47202573-6e83-42fd-a274-d11f05eca2dd_imageNS.125baba5-2bb1-443a-b457-bf74687481f5' is free, finding out if anyone is waiting for it. Thread-15824378::DEBUG::2016-09-15 11:17:36,587::resourceManager::619::Storage.ResourceManager::(releaseResource) Trying to release resource '47202573-6e83-42fd-a274-d11f05eca2dd_volumeNS.2d6c7d31-2bdb-49db-bf1b-9a9678534179' Thread-15824378::DEBUG::2016-09-15 11:17:36,587::resourceManager::638::Storage.ResourceManager::(releaseResource) Released resource '47202573-6e83-42fd-a274-d11f05eca2dd_volumeNS.2d6c7d31-2bdb-49db-bf1b-9a9678534179' (0 active users) Thread-15824378::DEBUG::2016-09-15 11:17:36,587::resourceManager::644::Storage.ResourceManager::(releaseResource) Resource '47202573-6e83-42fd-a274-d11f05eca2dd_volumeNS.2d6c7d31-2bdb-49db-bf1b-9a9678534179' is free, finding out if anyone is waiting for it. Thread-15824378::DEBUG::2016-09-15 11:17:36,587::resourceManager::652::Storage.ResourceManager::(releaseResource) No one is waiting for resource '47202573-6e83-42fd-a274-d11f05eca2dd_volumeNS.2d6c7d31-2bdb-49db-bf1b-9a9678534179', Clearing records. Thread-15824378::DEBUG::2016-09-15 11:17:36,587::resourceManager::619::Storage.ResourceManager::(releaseResource) Trying to release resource '47202573-6e83-42fd-a274-d11f05eca2dd_volumeNS.3d9b0244-fe0a-46dc-936d-4485166f821d' Thread-15824378::DEBUG::2016-09-15 11:17:36,588::resourceManager::638::Storage.ResourceManager::(releaseResource) Released resource '47202573-6e83-42fd-a274-d11f05eca2dd_volumeNS.3d9b0244-fe0a-46dc-936d-4485166f821d' (0 active users) Thread-15824378::DEBUG::2016-09-15 11:17:36,588::resourceManager::644::Storage.ResourceManager::(releaseResource) Resource '47202573-6e83-42fd-a274-d11f05eca2dd_volumeNS.3d9b0244-fe0a-46dc-936d-4485166f821d' is free, finding out if anyone is waiting for it. Thread-15824378::DEBUG::2016-09-15 11:17:36,588::resourceManager::652::Storage.ResourceManager::(releaseResource) No one is waiting for resource '47202573-6e83-42fd-a274-d11f05eca2dd_volumeNS.3d9b0244-fe0a-46dc-936d-4485166f821d', Clearing records. Thread-15824378::DEBUG::2016-09-15 11:17:36,588::resourceManager::652::Storage.ResourceManager::(releaseResource) No one is waiting for resource '47202573-6e83-42fd-a274-d11f05eca2dd_imageNS.125baba5-2bb1-443a-b457-bf74687481f5', Clearing records. Thread-15824378::INFO::2016-09-15 11:17:36,588::logUtils::51::dispatcher::(wrapper) Run and protect: imageSyncVolumeChain, Return response: None Thread-15824378::DEBUG::2016-09-15 11:17:36,588::task::1191::Storage.TaskManager.Task::(prepare) Task=`fc6fd5dd-58ad-46ef-9a20-764d5954eb0f`::finished: None Thread-15824378::DEBUG::2016-09-15 11:17:36,588::task::595::Storage.TaskManager.Task::(_updateState) Task=`fc6fd5dd-58ad-46ef-9a20-764d5954eb0f`::moving from state preparing -> state finished Thread-15824378::DEBUG::2016-09-15 11:17:36,589::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-15824378::DEBUG::2016-09-15 11:17:36,589::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-15824378::DEBUG::2016-09-15 11:17:36,589::task::993::Storage.TaskManager.Task::(_decref) Task=`fc6fd5dd-58ad-46ef-9a20-764d5954eb0f`::ref 0 aborting False Thread-15824378::INFO::2016-09-15 11:17:36,589::vm::5232::virt.vm::(tryPivot) vmId=`26afde81-07e2-46df-b118-8c72cb876227`::Requesting pivot to complete active layer commit (job 80f60e04-7283-4179-983c-cea1e607afb9) Thread-15824378::ERROR::2016-09-15 11:17:36,599::utils::739::root::(wrapper) Unhandled exception Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/vdsm/utils.py", line 736, in wrapper return f(*a, **kw) File "/usr/share/vdsm/virt/vm.py", line 5266, in run self.tryPivot() File "/usr/share/vdsm/virt/vm.py", line 5235, in tryPivot ret = self.vm._dom.blockJobAbort(self.drive.name, flags) File "/usr/share/vdsm/virt/virdomain.py", line 68, in f ret = attr(*args, **kwargs) File "/usr/lib/python2.7/site-packages/vdsm/libvirtconnection.py", line 124, in wrapper ret = f(*args, **kwargs) File "/usr/lib/python2.7/site-packages/vdsm/utils.py", line 1313, in wrapper return func(inst, *args, **kwargs) File "/usr/lib64/python2.7/site-packages/libvirt.py", line 733, in blockJobAbort if ret == -1: raise libvirtError ('virDomainBlockJobAbort() failed', dom=self) libvirtError: Block Kopieren ist immer noch aktiv: Disk 'vda' noch nicht bereit für Pivot Thread-15824377::DEBUG::2016-09-15 11:17:37,349::bindingxmlrpc::1269::vds::(wrapper) return vmGetIoTune with {'ioTune': [{'ioTune': {'write_bytes_sec': 0L, 'total_iops_sec': 0L, 'read_iops_sec': 0L, 'read_bytes_sec': 0L, 'write_iops_sec': 0L, 'total_bytes_sec': 0L}, 'path': u'/rhev/data-center/94ed7a19-fade-4bd6-83f2-2cbb2f730b95/47202573-6e83-42fd-a274-d11f05eca2dd/images/bca2217a-fc02-46ab-aea0-02add874192a/../bca2217a-fc02-46ab-aea0-02add874192a/a4cae242-2ae4-437d-8c52-cf23c30ea0e0', 'name': u'hda'}], 'status': {'message': 'Done', 'code': 0}} Thread-15824377::INFO::2016-09-15 11:17:37,351::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:46348 stopped Thread-12785652::DEBUG::2016-09-15 11:17:38,257::fileSD::173::Storage.Misc.excCmd::(getReadDelay) /usr/bin/taskset --cpu-list 0-31 /usr/bin/dd if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtEXP/63041fa9-e093-4b44-b36f-f39f16d3974f/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None) Thread-12785645::DEBUG::2016-09-15 11:17:38,308::fileSD::173::Storage.Misc.excCmd::(getReadDelay) /usr/bin/taskset --cpu-list 0-31 /usr/bin/dd if=/rhev/data-center/mnt/10.10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None) Thread-12785652::DEBUG::2016-09-15 11:17:38,386::fileSD::173::Storage.Misc.excCmd::(getReadDelay) SUCCESS: = '0+1 records in\n0+1 records out\n363 bytes (363 B) copied, 0.000342931 s, 1.1 MB/s\n'; = 0 Thread-12785648::DEBUG::2016-09-15 11:17:38,387::fileSD::173::Storage.Misc.excCmd::(getReadDelay) /usr/bin/taskset --cpu-list 0-31 /usr/bin/dd if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtISO/bff3a2be-fdd9-4e37-b416-fa4ef7fafba2/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None) Thread-12785645::DEBUG::2016-09-15 11:17:38,444::fileSD::173::Storage.Misc.excCmd::(getReadDelay) SUCCESS: = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.000274626 s, 2.0 MB/s\n'; = 0 Thread-12785648::DEBUG::2016-09-15 11:17:38,448::fileSD::173::Storage.Misc.excCmd::(getReadDelay) SUCCESS: = '0+1 records in\n0+1 records out\n357 bytes (357 B) copied, 0.000160654 s, 2.2 MB/s\n'; = 0 periodic/591483::DEBUG::2016-09-15 11:17:38,474::executor::183::Executor::(_run) Worker was discarded jsonrpc.Executor/2::DEBUG::2016-09-15 11:17:39,449::task::595::Storage.TaskManager.Task::(_updateState) Task=`3a0d3836-3fa5-4c30-89db-65379eb33c1a`::moving from state init -> state preparing jsonrpc.Executor/2::INFO::2016-09-15 11:17:39,449::logUtils::48::dispatcher::(wrapper) Run and protect: repoStats(options=None) jsonrpc.Executor/2::INFO::2016-09-15 11:17:39,450::logUtils::51::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'272ec473-6041-42ee-bd1a-732789dd18d4': {'code': 0, 'actual': True, 'version': 3, 'acquired': True, 'delay': '0.000274626', 'lastCheck': '1.0', 'valid': True}, '47202573-6e83-42fd-a274-d11f05eca2dd': {'code': 0, 'actual': True, 'version': 3, 'acquired': True, 'delay': '0.000366031', 'lastCheck': '6.0', 'valid': True}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000160654', 'lastCheck': '1.0', 'valid': True}, '63041fa9-e093-4b44-b36f-f39f16d3974f': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000342931', 'lastCheck': '1.0', 'valid': True}, '2c51d320-88ce-4f23-8215-e15f55f66906': {'code': 0, 'actual': True, 'version': 3, 'acquired': True, 'delay': '0.000200544', 'lastCheck': '9.7', 'valid': True}, 'c86d8409-4dd6-4e30-86dc-b5175a7ceb86': {'code': 0, 'actual': True, 'version': 3, 'acquired': True, 'delay': '0.000352086', 'lastCheck': '6.7', 'valid': True}} jsonrpc.Executor/2::DEBUG::2016-09-15 11:17:39,450::task::1191::Storage.TaskManager.Task::(prepare) Task=`3a0d3836-3fa5-4c30-89db-65379eb33c1a`::finished: {'272ec473-6041-42ee-bd1a-732789dd18d4': {'code': 0, 'actual': True, 'version': 3, 'acquired': True, 'delay': '0.000274626', 'lastCheck': '1.0', 'valid': True}, '47202573-6e83-42fd-a274-d11f05eca2dd': {'code': 0, 'actual': True, 'version': 3, 'acquired': True, 'delay': '0.000366031', 'lastCheck': '6.0', 'valid': True}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000160654', 'lastCheck': '1.0', 'valid': True}, '63041fa9-e093-4b44-b36f-f39f16d3974f': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000342931', 'lastCheck': '1.0', 'valid': True}, '2c51d320-88ce-4f23-8215-e15f55f66906': {'code': 0, 'actual': True, 'version': 3, 'acquired': True, 'delay': '0.000200544', 'lastCheck': '9.7', 'valid': True}, 'c86d8409-4dd6-4e30-86dc-b5175a7ceb86': {'code': 0, 'actual': True, 'version': 3, 'acquired': True, 'delay': '0.000352086', 'lastCheck': '6.7', 'valid': True}} jsonrpc.Executor/2::DEBUG::2016-09-15 11:17:39,450::task::595::Storage.TaskManager.Task::(_updateState) Task=`3a0d3836-3fa5-4c30-89db-65379eb33c1a`::moving from state preparing -> state finished jsonrpc.Executor/2::DEBUG::2016-09-15 11:17:39,450::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} jsonrpc.Executor/2::DEBUG::2016-09-15 11:17:39,450::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} jsonrpc.Executor/2::DEBUG::2016-09-15 11:17:39,451::task::993::Storage.TaskManager.Task::(_decref) Task=`3a0d3836-3fa5-4c30-89db-65379eb33c1a`::ref 0 aborting False Reactor thread::INFO::2016-09-15 11:17:39,677::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:46349 Reactor thread::DEBUG::2016-09-15 11:17:39,685::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11 Reactor thread::INFO::2016-09-15 11:17:39,685::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:46349 Reactor thread::DEBUG::2016-09-15 11:17:39,686::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 46349) BindingXMLRPC::INFO::2016-09-15 11:17:39,686::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:46349 Thread-15824379::INFO::2016-09-15 11:17:39,686::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:46349 started Thread-15824379::DEBUG::2016-09-15 11:17:39,688::bindingxmlrpc::1262::vds::(wrapper) client [127.0.0.1]::call vmGetIoTunePolicy with ('26afde81-07e2-46df-b118-8c72cb876227',) {} Thread-15824379::DEBUG::2016-09-15 11:17:39,689::bindingxmlrpc::1269::vds::(wrapper) return vmGetIoTunePolicy with {'ioTunePolicy': [], 'status': {'message': 'Done', 'code': 0}} Thread-15824379::INFO::2016-09-15 11:17:39,690::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:46349 stopped Reactor thread::INFO::2016-09-15 11:17:39,691::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:46350 Reactor thread::DEBUG::2016-09-15 11:17:39,698::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11 Reactor thread::INFO::2016-09-15 11:17:39,698::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:46350 Reactor thread::DEBUG::2016-09-15 11:17:39,699::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 46350) BindingXMLRPC::INFO::2016-09-15 11:17:39,699::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:46350 Thread-15824380::INFO::2016-09-15 11:17:39,700::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:46350 started Thread-15824380::DEBUG::2016-09-15 11:17:39,701::bindingxmlrpc::1262::vds::(wrapper) client [127.0.0.1]::call vmGetIoTune with ('26afde81-07e2-46df-b118-8c72cb876227',) {} Thread-12785623::DEBUG::2016-09-15 11:17:39,725::fileSD::173::Storage.Misc.excCmd::(getReadDelay) /usr/bin/taskset --cpu-list 0-31 /usr/bin/dd if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtIB/2c51d320-88ce-4f23-8215-e15f55f66906/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None) Thread-15824380::DEBUG::2016-09-15 11:17:39,807::bindingxmlrpc::1269::vds::(wrapper) return vmGetIoTune with {'ioTune': [{'ioTune': {'write_bytes_sec': 0L, 'total_iops_sec': 0L, 'read_iops_sec': 0L, 'read_bytes_sec': 0L, 'write_iops_sec': 0L, 'total_bytes_sec': 0L}, 'path': u'/rhev/data-center/94ed7a19-fade-4bd6-83f2-2cbb2f730b95/47202573-6e83-42fd-a274-d11f05eca2dd/images/125baba5-2bb1-443a-b457-bf74687481f5/3d9b0244-fe0a-46dc-936d-4485166f821d', 'name': u'vda'}, {'ioTune': {'write_bytes_sec': 0L, 'total_iops_sec': 0L, 'read_iops_sec': 0L, 'read_bytes_sec': 0L, 'write_iops_sec': 0L, 'total_bytes_sec': 0L}, 'path': u'/rhev/data-center/94ed7a19-fade-4bd6-83f2-2cbb2f730b95/47202573-6e83-42fd-a274-d11f05eca2dd/images/c471fa5b-4591-425a-bc33-c8644a0fd12c/2f974f55-842c-492b-8c04-8ed0a8ebaf93', 'name': u'vdb'}], 'status': {'message': 'Done', 'code': 0}} Thread-12785623::DEBUG::2016-09-15 11:17:39,811::fileSD::173::Storage.Misc.excCmd::(getReadDelay) SUCCESS: = '0+1 records in\n0+1 records out\n690 bytes (690 B) copied, 0.000160857 s, 4.3 MB/s\n'; = 0 Thread-15824380::INFO::2016-09-15 11:17:39,815::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:46350 stopped Reactor thread::INFO::2016-09-15 11:17:40,787::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:46351 Reactor thread::DEBUG::2016-09-15 11:17:40,794::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11 Reactor thread::INFO::2016-09-15 11:17:40,795::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:46351 Reactor thread::DEBUG::2016-09-15 11:17:40,795::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 46351) BindingXMLRPC::INFO::2016-09-15 11:17:40,796::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:46351 Thread-15824381::INFO::2016-09-15 11:17:40,796::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:46351 started Thread-15824381::DEBUG::2016-09-15 11:17:40,797::bindingxmlrpc::1262::vds::(wrapper) client [127.0.0.1]::call vmGetIoTunePolicy with ('76378288-3fc8-4321-a904-fb576318d881',) {} Thread-15824381::DEBUG::2016-09-15 11:17:40,798::bindingxmlrpc::1269::vds::(wrapper) return vmGetIoTunePolicy with {'ioTunePolicy': [], 'status': {'message': 'Done', 'code': 0}} Thread-15824381::INFO::2016-09-15 11:17:40,799::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:46351 stopped Reactor thread::INFO::2016-09-15 11:17:40,800::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:46352 Reactor thread::DEBUG::2016-09-15 11:17:40,807::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11 Reactor thread::INFO::2016-09-15 11:17:40,808::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:46352 Reactor thread::DEBUG::2016-09-15 11:17:40,808::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 46352) BindingXMLRPC::INFO::2016-09-15 11:17:40,809::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:46352 Thread-15824382::INFO::2016-09-15 11:17:40,809::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:46352 started Thread-15824382::DEBUG::2016-09-15 11:17:40,810::bindingxmlrpc::1262::vds::(wrapper) client [127.0.0.1]::call vmGetIoTune with ('76378288-3fc8-4321-a904-fb576318d881',) {} Thread-15824382::DEBUG::2016-09-15 11:17:40,813::bindingxmlrpc::1269::vds::(wrapper) return vmGetIoTune with {'ioTune': [{'ioTune': {'write_bytes_sec': 0L, 'total_iops_sec': 0L, 'read_iops_sec': 0L, 'read_bytes_sec': 0L, 'write_iops_sec': 0L, 'total_bytes_sec': 0L}, 'path': u'/rhev/data-center/94ed7a19-fade-4bd6-83f2-2cbb2f730b95/47202573-6e83-42fd-a274-d11f05eca2dd/images/8da41c96-a35e-4ca6-a256-92a67b280397/73ddde8b-9b5a-469a-8098-4d867dadf95c', 'name': u'sda'}], 'status': {'message': 'Done', 'code': 0}} Thread-15824382::INFO::2016-09-15 11:17:40,815::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:46352 stopped Thread-12785657::DEBUG::2016-09-15 11:17:42,720::fileSD::173::Storage.Misc.excCmd::(getReadDelay) /usr/bin/taskset --cpu-list 0-31 /usr/bin/dd if=/rhev/data-center/mnt/10.10.30.254:_var_nas4_OVirtIB/c86d8409-4dd6-4e30-86dc-b5175a7ceb86/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None) Thread-12785657::DEBUG::2016-09-15 11:17:42,807::fileSD::173::Storage.Misc.excCmd::(getReadDelay) SUCCESS: = '0+1 records in\n0+1 records out\n650 bytes (650 B) copied, 0.000204157 s, 3.2 MB/s\n'; = 0 Thread-12785646::DEBUG::2016-09-15 11:17:43,482::monitor::314::Storage.Monitor::(_refreshDomain) Refreshing domain 47202573-6e83-42fd-a274-d11f05eca2dd Thread-12785646::DEBUG::2016-09-15 11:17:43,491::fileSD::157::Storage.StorageDomainManifest::(__init__) Reading domain in path /rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/47202573-6e83-42fd-a274-d11f05eca2dd Thread-12785646::DEBUG::2016-09-15 11:17:43,491::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with FileMetadataRW backend Thread-12785646::DEBUG::2016-09-15 11:17:43,494::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=colnas01_IB', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'POOL_UUID=94ed7a19-fade-4bd6-83f2-2cbb2f730b95', 'REMOTE_PATH=10.10.30.251:/var/nas1/OVirtIB', 'ROLE=Regular', 'SDUUID=47202573-6e83-42fd-a274-d11f05eca2dd', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=eee97c141d19233070e290214bcf82cbdb800095'] Thread-12785646::DEBUG::2016-09-15 11:17:43,495::fileSD::671::Storage.StorageDomain::(imageGarbageCollector) Removing remnants of deleted images [] Thread-12785646::INFO::2016-09-15 11:17:43,495::sd::442::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace 47202573-6e83-42fd-a274-d11f05eca2dd_imageNS already registered Thread-12785646::INFO::2016-09-15 11:17:43,496::sd::450::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace 47202573-6e83-42fd-a274-d11f05eca2dd_volumeNS already registered Thread-12785646::DEBUG::2016-09-15 11:17:43,497::fileSD::173::Storage.Misc.excCmd::(getReadDelay) /usr/bin/taskset --cpu-list 0-31 /usr/bin/dd if=/rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/47202573-6e83-42fd-a274-d11f05eca2dd/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None) Thread-12785646::DEBUG::2016-09-15 11:17:43,583::fileSD::173::Storage.Misc.excCmd::(getReadDelay) SUCCESS: = '0+1 records in\n0+1 records out\n339 bytes (339 B) copied, 0.000153472 s, 2.2 MB/s\n'; = 0 Reactor thread::INFO::2016-09-15 11:17:45,855::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:46353 Reactor thread::DEBUG::2016-09-15 11:17:45,861::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11 Reactor thread::INFO::2016-09-15 11:17:45,862::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:46353 Reactor thread::DEBUG::2016-09-15 11:17:45,862::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 46353) BindingXMLRPC::INFO::2016-09-15 11:17:45,862::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:46353 Thread-15824389::INFO::2016-09-15 11:17:45,863::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:46353 started Thread-15824389::INFO::2016-09-15 11:17:45,893::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:46353 stopped Reactor thread::INFO::2016-09-15 11:17:45,895::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:46354 Reactor thread::DEBUG::2016-09-15 11:17:45,901::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11 Reactor thread::INFO::2016-09-15 11:17:45,901::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:46354 Reactor thread::DEBUG::2016-09-15 11:17:45,901::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 46354) BindingXMLRPC::INFO::2016-09-15 11:17:45,901::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:46354 Thread-15824390::INFO::2016-09-15 11:17:45,902::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:46354 started Thread-15824390::DEBUG::2016-09-15 11:17:45,902::bindingxmlrpc::1262::vds::(wrapper) client [127.0.0.1]::call vmGetIoTunePolicy with ('df64850b-eb40-4fd3-a54b-bcbd0bcb386b',) {} Thread-15824390::DEBUG::2016-09-15 11:17:45,903::bindingxmlrpc::1269::vds::(wrapper) return vmGetIoTunePolicy with {'ioTunePolicy': [], 'status': {'message': 'Done', 'code': 0}} Thread-15824390::INFO::2016-09-15 11:17:45,904::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:46354 stopped Reactor thread::INFO::2016-09-15 11:17:45,905::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:46355 Reactor thread::DEBUG::2016-09-15 11:17:45,911::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11 Reactor thread::INFO::2016-09-15 11:17:45,911::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:46355 Reactor thread::DEBUG::2016-09-15 11:17:45,911::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 46355) BindingXMLRPC::INFO::2016-09-15 11:17:45,911::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:46355 Thread-15824391::INFO::2016-09-15 11:17:45,912::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:46355 started Thread-15824391::DEBUG::2016-09-15 11:17:45,912::bindingxmlrpc::1262::vds::(wrapper) client [127.0.0.1]::call vmGetIoTune with ('df64850b-eb40-4fd3-a54b-bcbd0bcb386b',) {} Thread-15824391::DEBUG::2016-09-15 11:17:45,917::bindingxmlrpc::1269::vds::(wrapper) return vmGetIoTune with {'ioTune': [{'ioTune': {'write_bytes_sec': 0L, 'total_iops_sec': 0L, 'read_iops_sec': 0L, 'read_bytes_sec': 0L, 'write_iops_sec': 0L, 'total_bytes_sec': 0L}, 'path': u'/rhev/data-center/94ed7a19-fade-4bd6-83f2-2cbb2f730b95/c86d8409-4dd6-4e30-86dc-b5175a7ceb86/images/96a1c863-f9fd-4778-bedf-3cae66f8331b/e0648bf3-3552-4a4d-976e-eee9ccf0ac3e', 'name': u'vda'}, {'ioTune': {'write_bytes_sec': 0L, 'total_iops_sec': 0L, 'read_iops_sec': 0L, 'read_bytes_sec': 0L, 'write_iops_sec': 0L, 'total_bytes_sec': 0L}, 'path': u'/rhev/data-center/94ed7a19-fade-4bd6-83f2-2cbb2f730b95/c86d8409-4dd6-4e30-86dc-b5175a7ceb86/images/597d8ef7-5980-4ed1-9aab-92aca0456c11/be78a897-7470-464a-9971-960919d3fecf', 'name': u'vdb'}], 'status': {'message': 'Done', 'code': 0}} Thread-15824391::INFO::2016-09-15 11:17:45,919::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:46355 stopped Reactor thread::INFO::2016-09-15 11:17:47,054::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:46356 Reactor thread::DEBUG::2016-09-15 11:17:47,060::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11 Reactor thread::INFO::2016-09-15 11:17:47,060::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:46356 Reactor thread::DEBUG::2016-09-15 11:17:47,060::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 46356) BindingXMLRPC::INFO::2016-09-15 11:17:47,060::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:46356 Thread-15824392::INFO::2016-09-15 11:17:47,061::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:46356 started Thread-15824392::DEBUG::2016-09-15 11:17:47,061::bindingxmlrpc::1262::vds::(wrapper) client [127.0.0.1]::call vmGetIoTunePolicy with ('7740209b-a823-4d68-85f0-ec678f74f326',) {} Thread-15824392::DEBUG::2016-09-15 11:17:47,062::bindingxmlrpc::1269::vds::(wrapper) return vmGetIoTunePolicy with {'ioTunePolicy': [], 'status': {'message': 'Done', 'code': 0}} Thread-15824392::INFO::2016-09-15 11:17:47,063::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:46356 stopped Reactor thread::INFO::2016-09-15 11:17:47,064::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:46357 Reactor thread::INFO::2016-09-15 11:17:47,064::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:46358 Reactor thread::DEBUG::2016-09-15 11:17:47,070::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11 Reactor thread::DEBUG::2016-09-15 11:17:47,076::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11 Reactor thread::INFO::2016-09-15 11:17:47,076::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:46357 Reactor thread::DEBUG::2016-09-15 11:17:47,076::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 46357) Reactor thread::INFO::2016-09-15 11:17:47,077::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:46358 Reactor thread::DEBUG::2016-09-15 11:17:47,077::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 46358) BindingXMLRPC::INFO::2016-09-15 11:17:47,077::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:46357 BindingXMLRPC::INFO::2016-09-15 11:17:47,077::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:46358 Thread-15824393::INFO::2016-09-15 11:17:47,077::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:46357 started Thread-15824393::DEBUG::2016-09-15 11:17:47,078::bindingxmlrpc::1262::vds::(wrapper) client [127.0.0.1]::call vmGetIoTunePolicy with ('78d8e8f4-df95-44e0-ba8b-0922979fb3ac',) {} Thread-15824394::INFO::2016-09-15 11:17:47,078::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:46358 started Thread-15824394::DEBUG::2016-09-15 11:17:47,079::bindingxmlrpc::1262::vds::(wrapper) client [127.0.0.1]::call vmGetIoTune with ('7740209b-a823-4d68-85f0-ec678f74f326',) {} Reactor thread::INFO::2016-09-15 11:17:47,089::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:46359 Reactor thread::DEBUG::2016-09-15 11:17:47,102::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11 Reactor thread::INFO::2016-09-15 11:17:47,102::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:46359 Reactor thread::DEBUG::2016-09-15 11:17:47,103::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 46359) Reactor thread::INFO::2016-09-15 11:17:47,103::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:46360 BindingXMLRPC::INFO::2016-09-15 11:17:47,103::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:46359 Reactor thread::DEBUG::2016-09-15 11:17:47,108::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11 Reactor thread::INFO::2016-09-15 11:17:47,109::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:46360