Attachment 1137728 Details for Bug 1318902 – vdsm log

vdsm log

vdsm.log (text/plain), 218.27 KB, created by Yang Yang on 2016-03-18 09:29:48 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Yang Yang

Created: 2016-03-18 09:29:48 UTC

Size: 218.27 KB

patch

obsolete

>mailbox.SPMMonitor::DEBUG::2016-03-18 17:25:38,995::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) /usr/bin/taskset --cpu-list 0-1 dd if=/rhev/data-center/acc8b348-81f6-4bf2-9ffe-f1da755bb38d/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000 (cwd None)
>mailbox.SPMMonitor::DEBUG::2016-03-18 17:25:39,026::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0136184 s, 75.2 MB/s\n'; <rc> = 0
>Thread-43::DEBUG::2016-03-18 17:25:40,247::fileSD::173::Storage.Misc.excCmd::(getReadDelay) /usr/bin/taskset --cpu-list 0-1 /usr/bin/dd if=/rhev/data-center/mnt/10.73.194.27:_vol_S3_libvirtauto_yy_nfs1/c1d2e073-fa2e-47a9-8a0c-3ceefad91685/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
>Thread-43::DEBUG::2016-03-18 17:25:40,264::fileSD::173::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n467 bytes (467 B) copied, 0.000968067 s, 482 kB/s\n'; <rc> = 0
>mailbox.SPMMonitor::DEBUG::2016-03-18 17:25:41,039::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) /usr/bin/taskset --cpu-list 0-1 dd if=/rhev/data-center/acc8b348-81f6-4bf2-9ffe-f1da755bb38d/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000 (cwd None)
>mailbox.SPMMonitor::DEBUG::2016-03-18 17:25:41,071::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0137553 s, 74.4 MB/s\n'; <rc> = 0
>mailbox.SPMMonitor::DEBUG::2016-03-18 17:25:43,088::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) /usr/bin/taskset --cpu-list 0-1 dd if=/rhev/data-center/acc8b348-81f6-4bf2-9ffe-f1da755bb38d/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000 (cwd None)
>mailbox.SPMMonitor::DEBUG::2016-03-18 17:25:43,121::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0136911 s, 74.8 MB/s\n'; <rc> = 0
>jsonrpc.Executor/4::DEBUG::2016-03-18 17:25:43,635::task::595::Storage.TaskManager.Task::(_updateState) Task=`60abac4d-a37b-4c17-92cf-81fea3cfb64b`::moving from state init -> state preparing
>jsonrpc.Executor/4::INFO::2016-03-18 17:25:43,635::logUtils::48::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>jsonrpc.Executor/4::INFO::2016-03-18 17:25:43,635::logUtils::51::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'c1d2e073-fa2e-47a9-8a0c-3ceefad91685': {'code': 0, 'actual': True, 'version': 3, 'acquired': True, 'delay': '0.000968067', 'lastCheck': '3.4', 'valid': True}}
>jsonrpc.Executor/4::DEBUG::2016-03-18 17:25:43,636::task::1191::Storage.TaskManager.Task::(prepare) Task=`60abac4d-a37b-4c17-92cf-81fea3cfb64b`::finished: {u'c1d2e073-fa2e-47a9-8a0c-3ceefad91685': {'code': 0, 'actual': True, 'version': 3, 'acquired': True, 'delay': '0.000968067', 'lastCheck': '3.4', 'valid': True}}
>jsonrpc.Executor/4::DEBUG::2016-03-18 17:25:43,636::task::595::Storage.TaskManager.Task::(_updateState) Task=`60abac4d-a37b-4c17-92cf-81fea3cfb64b`::moving from state preparing -> state finished
>jsonrpc.Executor/4::DEBUG::2016-03-18 17:25:43,636::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>jsonrpc.Executor/4::DEBUG::2016-03-18 17:25:43,636::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>jsonrpc.Executor/4::DEBUG::2016-03-18 17:25:43,636::task::993::Storage.TaskManager.Task::(_decref) Task=`60abac4d-a37b-4c17-92cf-81fea3cfb64b`::ref 0 aborting False
>mailbox.SPMMonitor::DEBUG::2016-03-18 17:25:45,138::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) /usr/bin/taskset --cpu-list 0-1 dd if=/rhev/data-center/acc8b348-81f6-4bf2-9ffe-f1da755bb38d/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000 (cwd None)
>mailbox.SPMMonitor::DEBUG::2016-03-18 17:25:45,170::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0139054 s, 73.6 MB/s\n'; <rc> = 0
>jsonrpc.Executor/5::DEBUG::2016-03-18 17:25:45,641::__init__::503::jsonrpc.JsonRpcServer::(_serveRequest) Calling 'StoragePool.getSpmStatus' in bridge with {u'storagepoolID': u'acc8b348-81f6-4bf2-9ffe-f1da755bb38d'}
>jsonrpc.Executor/5::DEBUG::2016-03-18 17:25:45,642::task::595::Storage.TaskManager.Task::(_updateState) Task=`f3498feb-402a-497f-8f42-e3e44bf9c133`::moving from state init -> state preparing
>jsonrpc.Executor/5::INFO::2016-03-18 17:25:45,643::logUtils::48::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID=u'acc8b348-81f6-4bf2-9ffe-f1da755bb38d', options=None)
>jsonrpc.Executor/5::INFO::2016-03-18 17:25:45,657::logUtils::51::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 2L}}
>jsonrpc.Executor/5::DEBUG::2016-03-18 17:25:45,658::task::1191::Storage.TaskManager.Task::(prepare) Task=`f3498feb-402a-497f-8f42-e3e44bf9c133`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 2L}}
>jsonrpc.Executor/5::DEBUG::2016-03-18 17:25:45,658::task::595::Storage.TaskManager.Task::(_updateState) Task=`f3498feb-402a-497f-8f42-e3e44bf9c133`::moving from state preparing -> state finished
>jsonrpc.Executor/5::DEBUG::2016-03-18 17:25:45,658::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>jsonrpc.Executor/5::DEBUG::2016-03-18 17:25:45,658::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>jsonrpc.Executor/5::DEBUG::2016-03-18 17:25:45,659::task::993::Storage.TaskManager.Task::(_decref) Task=`f3498feb-402a-497f-8f42-e3e44bf9c133`::ref 0 aborting False
>jsonrpc.Executor/5::DEBUG::2016-03-18 17:25:45,659::__init__::533::jsonrpc.JsonRpcServer::(_serveRequest) Return 'StoragePool.getSpmStatus' in bridge with {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 2L}
>jsonrpc.Executor/6::DEBUG::2016-03-18 17:25:46,671::__init__::503::jsonrpc.JsonRpcServer::(_serveRequest) Calling 'StoragePool.getInfo' in bridge with {u'storagepoolID': u'acc8b348-81f6-4bf2-9ffe-f1da755bb38d'}
>jsonrpc.Executor/6::DEBUG::2016-03-18 17:25:46,672::task::595::Storage.TaskManager.Task::(_updateState) Task=`6c578f8f-0812-4371-9a4f-b828519406ed`::moving from state init -> state preparing
>jsonrpc.Executor/6::INFO::2016-03-18 17:25:46,672::logUtils::48::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID=u'acc8b348-81f6-4bf2-9ffe-f1da755bb38d', options=None)
>jsonrpc.Executor/6::DEBUG::2016-03-18 17:25:46,673::resourceManager::199::Storage.ResourceManager.Request::(__init__) ResName=`Storage.acc8b348-81f6-4bf2-9ffe-f1da755bb38d`ReqID=`6a26d327-e336-422e-b5d5-cc894416479b`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2642' at 'getStoragePoolInfo'
>jsonrpc.Executor/6::DEBUG::2016-03-18 17:25:46,673::resourceManager::545::Storage.ResourceManager::(registerResource) Trying to register resource 'Storage.acc8b348-81f6-4bf2-9ffe-f1da755bb38d' for lock type 'shared'
>jsonrpc.Executor/6::DEBUG::2016-03-18 17:25:46,674::resourceManager::604::Storage.ResourceManager::(registerResource) Resource 'Storage.acc8b348-81f6-4bf2-9ffe-f1da755bb38d' is free. Now locking as 'shared' (1 active user)
>jsonrpc.Executor/6::DEBUG::2016-03-18 17:25:46,674::resourceManager::239::Storage.ResourceManager.Request::(grant) ResName=`Storage.acc8b348-81f6-4bf2-9ffe-f1da755bb38d`ReqID=`6a26d327-e336-422e-b5d5-cc894416479b`::Granted request
>jsonrpc.Executor/6::DEBUG::2016-03-18 17:25:46,674::task::827::Storage.TaskManager.Task::(resourceAcquired) Task=`6c578f8f-0812-4371-9a4f-b828519406ed`::_resourcesAcquired: Storage.acc8b348-81f6-4bf2-9ffe-f1da755bb38d (shared)
>jsonrpc.Executor/6::DEBUG::2016-03-18 17:25:46,675::task::993::Storage.TaskManager.Task::(_decref) Task=`6c578f8f-0812-4371-9a4f-b828519406ed`::ref 1 aborting False
>jsonrpc.Executor/6::INFO::2016-03-18 17:25:46,693::logUtils::51::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'No Description', 'isoprefix': '', 'pool_status': 'connected', 'lver': 2L, 'domains': u'c1d2e073-fa2e-47a9-8a0c-3ceefad91685:Active', 'master_uuid': u'c1d2e073-fa2e-47a9-8a0c-3ceefad91685', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {u'c1d2e073-fa2e-47a9-8a0c-3ceefad91685': {'status': u'Active', 'diskfree': '159251103744', 'isoprefix': '', 'alerts': [], 'disktotal': '322122547200', 'version': 3}}}
>jsonrpc.Executor/6::DEBUG::2016-03-18 17:25:46,694::task::1191::Storage.TaskManager.Task::(prepare) Task=`6c578f8f-0812-4371-9a4f-b828519406ed`::finished: {'info': {'name': 'No Description', 'isoprefix': '', 'pool_status': 'connected', 'lver': 2L, 'domains': u'c1d2e073-fa2e-47a9-8a0c-3ceefad91685:Active', 'master_uuid': u'c1d2e073-fa2e-47a9-8a0c-3ceefad91685', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {u'c1d2e073-fa2e-47a9-8a0c-3ceefad91685': {'status': u'Active', 'diskfree': '159251103744', 'isoprefix': '', 'alerts': [], 'disktotal': '322122547200', 'version': 3}}}
>jsonrpc.Executor/6::DEBUG::2016-03-18 17:25:46,694::task::595::Storage.TaskManager.Task::(_updateState) Task=`6c578f8f-0812-4371-9a4f-b828519406ed`::moving from state preparing -> state finished
>jsonrpc.Executor/6::DEBUG::2016-03-18 17:25:46,694::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {u'Storage.acc8b348-81f6-4bf2-9ffe-f1da755bb38d': < ResourceRef 'Storage.acc8b348-81f6-4bf2-9ffe-f1da755bb38d', isValid: 'True' obj: 'None'>}
>jsonrpc.Executor/6::DEBUG::2016-03-18 17:25:46,694::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>jsonrpc.Executor/6::DEBUG::2016-03-18 17:25:46,695::resourceManager::619::Storage.ResourceManager::(releaseResource) Trying to release resource 'Storage.acc8b348-81f6-4bf2-9ffe-f1da755bb38d'
>jsonrpc.Executor/6::DEBUG::2016-03-18 17:25:46,695::resourceManager::638::Storage.ResourceManager::(releaseResource) Released resource 'Storage.acc8b348-81f6-4bf2-9ffe-f1da755bb38d' (0 active users)
>jsonrpc.Executor/6::DEBUG::2016-03-18 17:25:46,695::resourceManager::644::Storage.ResourceManager::(releaseResource) Resource 'Storage.acc8b348-81f6-4bf2-9ffe-f1da755bb38d' is free, finding out if anyone is waiting for it.
>jsonrpc.Executor/6::DEBUG::2016-03-18 17:25:46,695::resourceManager::652::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'Storage.acc8b348-81f6-4bf2-9ffe-f1da755bb38d', Clearing records.
>jsonrpc.Executor/6::DEBUG::2016-03-18 17:25:46,696::task::993::Storage.TaskManager.Task::(_decref) Task=`6c578f8f-0812-4371-9a4f-b828519406ed`::ref 0 aborting False
>jsonrpc.Executor/6::DEBUG::2016-03-18 17:25:46,696::__init__::533::jsonrpc.JsonRpcServer::(_serveRequest) Return 'StoragePool.getInfo' in bridge with {'info': {'name': 'No Description', 'isoprefix': '', 'pool_status': 'connected', 'lver': 2L, 'domains': u'c1d2e073-fa2e-47a9-8a0c-3ceefad91685:Active', 'master_uuid': u'c1d2e073-fa2e-47a9-8a0c-3ceefad91685', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {u'c1d2e073-fa2e-47a9-8a0c-3ceefad91685': {'status': u'Active', 'diskfree': '159251103744', 'isoprefix': '', 'alerts': [], 'disktotal': '322122547200', 'version': 3}}}
>Reactor thread::INFO::2016-03-18 17:25:46,702::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:58370
>Reactor thread::DEBUG::2016-03-18 17:25:46,711::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11
>Reactor thread::INFO::2016-03-18 17:25:46,712::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:58370
>Reactor thread::DEBUG::2016-03-18 17:25:46,712::bindingxmlrpc::1297::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 58370)
>BindingXMLRPC::INFO::2016-03-18 17:25:46,712::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:58370
>Thread-74::INFO::2016-03-18 17:25:46,713::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:58370 started
>Thread-74::INFO::2016-03-18 17:25:46,716::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:58370 stopped
>mailbox.SPMMonitor::DEBUG::2016-03-18 17:25:47,183::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) /usr/bin/taskset --cpu-list 0-1 dd if=/rhev/data-center/acc8b348-81f6-4bf2-9ffe-f1da755bb38d/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000 (cwd None)
>mailbox.SPMMonitor::DEBUG::2016-03-18 17:25:47,214::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0136435 s, 75.1 MB/s\n'; <rc> = 0
>jsonrpc.Executor/0::DEBUG::2016-03-18 17:25:47,712::__init__::503::jsonrpc.JsonRpcServer::(_serveRequest) Calling 'Volume.create' in bridge with {u'preallocate': 2, u'volFormat': 5, u'srcImgUUID': u'00000000-0000-0000-0000-000000000000', u'volumeID': u'81610d39-bca1-4c94-b193-fae83a8a1912', u'imageID': u'e7e0392e-bcb9-4486-9e41-e163296528f5', u'storagepoolID': u'acc8b348-81f6-4bf2-9ffe-f1da755bb38d', u'storagedomainID': u'c1d2e073-fa2e-47a9-8a0c-3ceefad91685', u'desc': u'{"DiskAlias":"vm1_Disk1","DiskDescription":""}', u'diskType': 2, u'srcVolUUID': u'00000000-0000-0000-0000-000000000000', u'size': u'5368709120'}
>jsonrpc.Executor/0::DEBUG::2016-03-18 17:25:47,713::task::595::Storage.TaskManager.Task::(_updateState) Task=`bf00aa4b-05bc-49bc-9e12-4350a314308e`::moving from state init -> state preparing
>jsonrpc.Executor/0::INFO::2016-03-18 17:25:47,714::logUtils::48::dispatcher::(wrapper) Run and protect: createVolume(sdUUID=u'c1d2e073-fa2e-47a9-8a0c-3ceefad91685', spUUID=u'acc8b348-81f6-4bf2-9ffe-f1da755bb38d', imgUUID=u'e7e0392e-bcb9-4486-9e41-e163296528f5', size=u'5368709120', volFormat=5, preallocate=2, diskType=2, volUUID=u'81610d39-bca1-4c94-b193-fae83a8a1912', desc=u'{"DiskAlias":"vm1_Disk1","DiskDescription":""}', srcImgUUID=u'00000000-0000-0000-0000-000000000000', srcVolUUID=u'00000000-0000-0000-0000-000000000000', initialSize=None)
>jsonrpc.Executor/0::DEBUG::2016-03-18 17:25:47,715::resourceManager::199::Storage.ResourceManager.Request::(__init__) ResName=`Storage.c1d2e073-fa2e-47a9-8a0c-3ceefad91685`ReqID=`097a046f-ccfe-4717-95fa-4ee87334eec7`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '1473' at 'createVolume'
>jsonrpc.Executor/0::DEBUG::2016-03-18 17:25:47,715::resourceManager::545::Storage.ResourceManager::(registerResource) Trying to register resource 'Storage.c1d2e073-fa2e-47a9-8a0c-3ceefad91685' for lock type 'shared'
>jsonrpc.Executor/0::DEBUG::2016-03-18 17:25:47,716::resourceManager::604::Storage.ResourceManager::(registerResource) Resource 'Storage.c1d2e073-fa2e-47a9-8a0c-3ceefad91685' is free. Now locking as 'shared' (1 active user)
>jsonrpc.Executor/0::DEBUG::2016-03-18 17:25:47,716::resourceManager::239::Storage.ResourceManager.Request::(grant) ResName=`Storage.c1d2e073-fa2e-47a9-8a0c-3ceefad91685`ReqID=`097a046f-ccfe-4717-95fa-4ee87334eec7`::Granted request
>jsonrpc.Executor/0::DEBUG::2016-03-18 17:25:47,716::task::827::Storage.TaskManager.Task::(resourceAcquired) Task=`bf00aa4b-05bc-49bc-9e12-4350a314308e`::_resourcesAcquired: Storage.c1d2e073-fa2e-47a9-8a0c-3ceefad91685 (shared)
>jsonrpc.Executor/0::DEBUG::2016-03-18 17:25:47,717::task::993::Storage.TaskManager.Task::(_decref) Task=`bf00aa4b-05bc-49bc-9e12-4350a314308e`::ref 1 aborting False
>jsonrpc.Executor/0::DEBUG::2016-03-18 17:25:47,717::__init__::320::IOProcessClient::(_run) Starting IOProcess...
>jsonrpc.Executor/0::DEBUG::2016-03-18 17:25:47,747::task::752::Storage.TaskManager.Task::(_save) Task=`bf00aa4b-05bc-49bc-9e12-4350a314308e`::_save: orig /rhev/data-center/acc8b348-81f6-4bf2-9ffe-f1da755bb38d/mastersd/master/tasks/bf00aa4b-05bc-49bc-9e12-4350a314308e temp /rhev/data-center/acc8b348-81f6-4bf2-9ffe-f1da755bb38d/mastersd/master/tasks/bf00aa4b-05bc-49bc-9e12-4350a314308e.temp
>jsonrpc.Executor/0::DEBUG::2016-03-18 17:25:47,797::taskManager::78::Storage.TaskManager::(scheduleJob) scheduled job createVolume for task bf00aa4b-05bc-49bc-9e12-4350a314308e 
>jsonrpc.Executor/0::INFO::2016-03-18 17:25:47,797::logUtils::51::dispatcher::(wrapper) Run and protect: createVolume, Return response: None
>jsonrpc.Executor/0::DEBUG::2016-03-18 17:25:47,797::task::1183::Storage.TaskManager.Task::(prepare) Task=`bf00aa4b-05bc-49bc-9e12-4350a314308e`::Prepare: 1 jobs exist, move to acquiring
>jsonrpc.Executor/0::DEBUG::2016-03-18 17:25:47,797::task::595::Storage.TaskManager.Task::(_updateState) Task=`bf00aa4b-05bc-49bc-9e12-4350a314308e`::moving from state preparing -> state acquiring
>jsonrpc.Executor/0::DEBUG::2016-03-18 17:25:47,799::task::752::Storage.TaskManager.Task::(_save) Task=`bf00aa4b-05bc-49bc-9e12-4350a314308e`::_save: orig /rhev/data-center/acc8b348-81f6-4bf2-9ffe-f1da755bb38d/mastersd/master/tasks/bf00aa4b-05bc-49bc-9e12-4350a314308e temp /rhev/data-center/acc8b348-81f6-4bf2-9ffe-f1da755bb38d/mastersd/master/tasks/bf00aa4b-05bc-49bc-9e12-4350a314308e.temp
>jsonrpc.Executor/0::DEBUG::2016-03-18 17:25:47,827::task::595::Storage.TaskManager.Task::(_updateState) Task=`bf00aa4b-05bc-49bc-9e12-4350a314308e`::moving from state acquiring -> state queued
>jsonrpc.Executor/0::DEBUG::2016-03-18 17:25:47,829::task::752::Storage.TaskManager.Task::(_save) Task=`bf00aa4b-05bc-49bc-9e12-4350a314308e`::_save: orig /rhev/data-center/acc8b348-81f6-4bf2-9ffe-f1da755bb38d/mastersd/master/tasks/bf00aa4b-05bc-49bc-9e12-4350a314308e temp /rhev/data-center/acc8b348-81f6-4bf2-9ffe-f1da755bb38d/mastersd/master/tasks/bf00aa4b-05bc-49bc-9e12-4350a314308e.temp
>jsonrpc.Executor/0::DEBUG::2016-03-18 17:25:47,858::taskManager::56::Storage.TaskManager::(_queueTask) queuing task: bf00aa4b-05bc-49bc-9e12-4350a314308e
>jsonrpc.Executor/0::DEBUG::2016-03-18 17:25:47,858::taskManager::64::Storage.TaskManager::(_queueTask) task queued: bf00aa4b-05bc-49bc-9e12-4350a314308e
>jsonrpc.Executor/0::DEBUG::2016-03-18 17:25:47,859::task::1188::Storage.TaskManager.Task::(prepare) Task=`bf00aa4b-05bc-49bc-9e12-4350a314308e`::returning
>jsonrpc.Executor/0::DEBUG::2016-03-18 17:25:47,859::task::993::Storage.TaskManager.Task::(_decref) Task=`bf00aa4b-05bc-49bc-9e12-4350a314308e`::ref 0 aborting False
>jsonrpc.Executor/0::DEBUG::2016-03-18 17:25:47,859::__init__::533::jsonrpc.JsonRpcServer::(_serveRequest) Return 'Volume.create' in bridge with bf00aa4b-05bc-49bc-9e12-4350a314308e
>d1c2d880-b254-4cce-8fe9-9e3f3cbf19de::DEBUG::2016-03-18 17:25:47,860::threadPool::51::Storage.ThreadPool::(setRunningTask) Number of running tasks: 1
>bf00aa4b-05bc-49bc-9e12-4350a314308e::DEBUG::2016-03-18 17:25:47,860::threadPool::194::Storage.ThreadPool.WorkerThread::(_processNextTask) Task: bf00aa4b-05bc-49bc-9e12-4350a314308e running: <bound method Task.commit of <storage.task.Task instance at 0x7fac5c0c13b0>> with: None
>bf00aa4b-05bc-49bc-9e12-4350a314308e::DEBUG::2016-03-18 17:25:47,860::task::1200::Storage.TaskManager.Task::(commit) Task=`bf00aa4b-05bc-49bc-9e12-4350a314308e`::committing task: bf00aa4b-05bc-49bc-9e12-4350a314308e
>bf00aa4b-05bc-49bc-9e12-4350a314308e::DEBUG::2016-03-18 17:25:47,860::task::595::Storage.TaskManager.Task::(_updateState) Task=`bf00aa4b-05bc-49bc-9e12-4350a314308e`::moving from state queued -> state running
>bf00aa4b-05bc-49bc-9e12-4350a314308e::DEBUG::2016-03-18 17:25:47,863::task::752::Storage.TaskManager.Task::(_save) Task=`bf00aa4b-05bc-49bc-9e12-4350a314308e`::_save: orig /rhev/data-center/acc8b348-81f6-4bf2-9ffe-f1da755bb38d/mastersd/master/tasks/bf00aa4b-05bc-49bc-9e12-4350a314308e temp /rhev/data-center/acc8b348-81f6-4bf2-9ffe-f1da755bb38d/mastersd/master/tasks/bf00aa4b-05bc-49bc-9e12-4350a314308e.temp
>bf00aa4b-05bc-49bc-9e12-4350a314308e::DEBUG::2016-03-18 17:25:47,895::task::905::Storage.TaskManager.Task::(_runJobs) Task=`bf00aa4b-05bc-49bc-9e12-4350a314308e`::Task.run: running job 0: createVolume: <bound method StoragePool.createVolume of <storage.sp.StoragePool object at 0x3790fd0>> (args: (u'c1d2e073-fa2e-47a9-8a0c-3ceefad91685', u'e7e0392e-bcb9-4486-9e41-e163296528f5', 10485760, 5, 2, 2, u'81610d39-bca1-4c94-b193-fae83a8a1912', u'{"DiskAlias":"vm1_Disk1","DiskDescription":""}', u'00000000-0000-0000-0000-000000000000', u'00000000-0000-0000-0000-000000000000', None) kwargs: {})
>bf00aa4b-05bc-49bc-9e12-4350a314308e::DEBUG::2016-03-18 17:25:47,896::task::329::Storage.TaskManager.Task::(run) Task=`bf00aa4b-05bc-49bc-9e12-4350a314308e`::Job.run: running createVolume: <bound method StoragePool.createVolume of <storage.sp.StoragePool object at 0x3790fd0>> (args: (u'c1d2e073-fa2e-47a9-8a0c-3ceefad91685', u'e7e0392e-bcb9-4486-9e41-e163296528f5', 10485760, 5, 2, 2, u'81610d39-bca1-4c94-b193-fae83a8a1912', u'{"DiskAlias":"vm1_Disk1","DiskDescription":""}', u'00000000-0000-0000-0000-000000000000', u'00000000-0000-0000-0000-000000000000', None) kwargs: {}) callback None
>bf00aa4b-05bc-49bc-9e12-4350a314308e::DEBUG::2016-03-18 17:25:47,897::resourceManager::199::Storage.ResourceManager.Request::(__init__) ResName=`c1d2e073-fa2e-47a9-8a0c-3ceefad91685_imageNS.e7e0392e-bcb9-4486-9e41-e163296528f5`ReqID=`774cb93c-2514-4660-8095-72ae087ecd1f`::Request was made in '/usr/share/vdsm/storage/sp.py' line '1925' at 'createVolume'
>bf00aa4b-05bc-49bc-9e12-4350a314308e::DEBUG::2016-03-18 17:25:47,897::resourceManager::545::Storage.ResourceManager::(registerResource) Trying to register resource 'c1d2e073-fa2e-47a9-8a0c-3ceefad91685_imageNS.e7e0392e-bcb9-4486-9e41-e163296528f5' for lock type 'exclusive'
>bf00aa4b-05bc-49bc-9e12-4350a314308e::DEBUG::2016-03-18 17:25:47,900::resourceFactories::125::Storage.ResourcesFactories::(__getResourceCandidatesList) Image e7e0392e-bcb9-4486-9e41-e163296528f5 does not exist in domain c1d2e073-fa2e-47a9-8a0c-3ceefad91685
>bf00aa4b-05bc-49bc-9e12-4350a314308e::DEBUG::2016-03-18 17:25:47,900::resourceManager::604::Storage.ResourceManager::(registerResource) Resource 'c1d2e073-fa2e-47a9-8a0c-3ceefad91685_imageNS.e7e0392e-bcb9-4486-9e41-e163296528f5' is free. Now locking as 'exclusive' (1 active user)
>bf00aa4b-05bc-49bc-9e12-4350a314308e::DEBUG::2016-03-18 17:25:47,901::resourceManager::239::Storage.ResourceManager.Request::(grant) ResName=`c1d2e073-fa2e-47a9-8a0c-3ceefad91685_imageNS.e7e0392e-bcb9-4486-9e41-e163296528f5`ReqID=`774cb93c-2514-4660-8095-72ae087ecd1f`::Granted request
>bf00aa4b-05bc-49bc-9e12-4350a314308e::INFO::2016-03-18 17:25:47,901::image::125::Storage.Image::(create) Create placeholder /rhev/data-center/acc8b348-81f6-4bf2-9ffe-f1da755bb38d/c1d2e073-fa2e-47a9-8a0c-3ceefad91685/images/e7e0392e-bcb9-4486-9e41-e163296528f5 for image's volumes
>bf00aa4b-05bc-49bc-9e12-4350a314308e::DEBUG::2016-03-18 17:25:47,903::task::752::Storage.TaskManager.Task::(_save) Task=`bf00aa4b-05bc-49bc-9e12-4350a314308e`::_save: orig /rhev/data-center/acc8b348-81f6-4bf2-9ffe-f1da755bb38d/mastersd/master/tasks/bf00aa4b-05bc-49bc-9e12-4350a314308e temp /rhev/data-center/acc8b348-81f6-4bf2-9ffe-f1da755bb38d/mastersd/master/tasks/bf00aa4b-05bc-49bc-9e12-4350a314308e.temp
>bf00aa4b-05bc-49bc-9e12-4350a314308e::INFO::2016-03-18 17:25:47,937::volume::455::Storage.Volume::(create) Creating volume 81610d39-bca1-4c94-b193-fae83a8a1912
>bf00aa4b-05bc-49bc-9e12-4350a314308e::DEBUG::2016-03-18 17:25:47,939::task::752::Storage.TaskManager.Task::(_save) Task=`bf00aa4b-05bc-49bc-9e12-4350a314308e`::_save: orig /rhev/data-center/acc8b348-81f6-4bf2-9ffe-f1da755bb38d/mastersd/master/tasks/bf00aa4b-05bc-49bc-9e12-4350a314308e temp /rhev/data-center/acc8b348-81f6-4bf2-9ffe-f1da755bb38d/mastersd/master/tasks/bf00aa4b-05bc-49bc-9e12-4350a314308e.temp
>bf00aa4b-05bc-49bc-9e12-4350a314308e::DEBUG::2016-03-18 17:25:47,978::task::752::Storage.TaskManager.Task::(_save) Task=`bf00aa4b-05bc-49bc-9e12-4350a314308e`::_save: orig /rhev/data-center/acc8b348-81f6-4bf2-9ffe-f1da755bb38d/mastersd/master/tasks/bf00aa4b-05bc-49bc-9e12-4350a314308e temp /rhev/data-center/acc8b348-81f6-4bf2-9ffe-f1da755bb38d/mastersd/master/tasks/bf00aa4b-05bc-49bc-9e12-4350a314308e.temp
>bf00aa4b-05bc-49bc-9e12-4350a314308e::INFO::2016-03-18 17:25:48,052::fileVolume::139::Storage.Volume::(_create) Request to create RAW volume /rhev/data-center/acc8b348-81f6-4bf2-9ffe-f1da755bb38d/c1d2e073-fa2e-47a9-8a0c-3ceefad91685/images/e7e0392e-bcb9-4486-9e41-e163296528f5/81610d39-bca1-4c94-b193-fae83a8a1912 with size = 10485760 sectors
>bf00aa4b-05bc-49bc-9e12-4350a314308e::DEBUG::2016-03-18 17:25:48,057::task::752::Storage.TaskManager.Task::(_save) Task=`bf00aa4b-05bc-49bc-9e12-4350a314308e`::_save: orig /rhev/data-center/acc8b348-81f6-4bf2-9ffe-f1da755bb38d/mastersd/master/tasks/bf00aa4b-05bc-49bc-9e12-4350a314308e temp /rhev/data-center/acc8b348-81f6-4bf2-9ffe-f1da755bb38d/mastersd/master/tasks/bf00aa4b-05bc-49bc-9e12-4350a314308e.temp
>bf00aa4b-05bc-49bc-9e12-4350a314308e::DEBUG::2016-03-18 17:25:48,112::fileVolume::390::Storage.Volume::(newVolumeLease) Initializing volume lease volUUID=81610d39-bca1-4c94-b193-fae83a8a1912 sdUUID=c1d2e073-fa2e-47a9-8a0c-3ceefad91685, metaId=(u'/rhev/data-center/acc8b348-81f6-4bf2-9ffe-f1da755bb38d/c1d2e073-fa2e-47a9-8a0c-3ceefad91685/images/e7e0392e-bcb9-4486-9e41-e163296528f5/81610d39-bca1-4c94-b193-fae83a8a1912',)
>bf00aa4b-05bc-49bc-9e12-4350a314308e::DEBUG::2016-03-18 17:25:48,147::task::752::Storage.TaskManager.Task::(_save) Task=`bf00aa4b-05bc-49bc-9e12-4350a314308e`::_save: orig /rhev/data-center/acc8b348-81f6-4bf2-9ffe-f1da755bb38d/mastersd/master/tasks/bf00aa4b-05bc-49bc-9e12-4350a314308e temp /rhev/data-center/acc8b348-81f6-4bf2-9ffe-f1da755bb38d/mastersd/master/tasks/bf00aa4b-05bc-49bc-9e12-4350a314308e.temp
>bf00aa4b-05bc-49bc-9e12-4350a314308e::DEBUG::2016-03-18 17:25:48,201::resourceManager::619::Storage.ResourceManager::(releaseResource) Trying to release resource 'c1d2e073-fa2e-47a9-8a0c-3ceefad91685_imageNS.e7e0392e-bcb9-4486-9e41-e163296528f5'
>bf00aa4b-05bc-49bc-9e12-4350a314308e::DEBUG::2016-03-18 17:25:48,201::resourceManager::638::Storage.ResourceManager::(releaseResource) Released resource 'c1d2e073-fa2e-47a9-8a0c-3ceefad91685_imageNS.e7e0392e-bcb9-4486-9e41-e163296528f5' (0 active users)
>bf00aa4b-05bc-49bc-9e12-4350a314308e::DEBUG::2016-03-18 17:25:48,201::resourceManager::644::Storage.ResourceManager::(releaseResource) Resource 'c1d2e073-fa2e-47a9-8a0c-3ceefad91685_imageNS.e7e0392e-bcb9-4486-9e41-e163296528f5' is free, finding out if anyone is waiting for it.
>bf00aa4b-05bc-49bc-9e12-4350a314308e::DEBUG::2016-03-18 17:25:48,201::resourceManager::652::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'c1d2e073-fa2e-47a9-8a0c-3ceefad91685_imageNS.e7e0392e-bcb9-4486-9e41-e163296528f5', Clearing records.
>bf00aa4b-05bc-49bc-9e12-4350a314308e::DEBUG::2016-03-18 17:25:48,202::task::595::Storage.TaskManager.Task::(_updateState) Task=`bf00aa4b-05bc-49bc-9e12-4350a314308e`::moving from state running -> state finished
>bf00aa4b-05bc-49bc-9e12-4350a314308e::DEBUG::2016-03-18 17:25:48,204::task::752::Storage.TaskManager.Task::(_save) Task=`bf00aa4b-05bc-49bc-9e12-4350a314308e`::_save: orig /rhev/data-center/acc8b348-81f6-4bf2-9ffe-f1da755bb38d/mastersd/master/tasks/bf00aa4b-05bc-49bc-9e12-4350a314308e temp /rhev/data-center/acc8b348-81f6-4bf2-9ffe-f1da755bb38d/mastersd/master/tasks/bf00aa4b-05bc-49bc-9e12-4350a314308e.temp
>bf00aa4b-05bc-49bc-9e12-4350a314308e::DEBUG::2016-03-18 17:25:48,250::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {u'Storage.c1d2e073-fa2e-47a9-8a0c-3ceefad91685': < ResourceRef 'Storage.c1d2e073-fa2e-47a9-8a0c-3ceefad91685', isValid: 'True' obj: 'None'>}
>bf00aa4b-05bc-49bc-9e12-4350a314308e::DEBUG::2016-03-18 17:25:48,250::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>bf00aa4b-05bc-49bc-9e12-4350a314308e::DEBUG::2016-03-18 17:25:48,250::resourceManager::619::Storage.ResourceManager::(releaseResource) Trying to release resource 'Storage.c1d2e073-fa2e-47a9-8a0c-3ceefad91685'
>bf00aa4b-05bc-49bc-9e12-4350a314308e::DEBUG::2016-03-18 17:25:48,251::resourceManager::638::Storage.ResourceManager::(releaseResource) Released resource 'Storage.c1d2e073-fa2e-47a9-8a0c-3ceefad91685' (0 active users)
>bf00aa4b-05bc-49bc-9e12-4350a314308e::DEBUG::2016-03-18 17:25:48,251::resourceManager::644::Storage.ResourceManager::(releaseResource) Resource 'Storage.c1d2e073-fa2e-47a9-8a0c-3ceefad91685' is free, finding out if anyone is waiting for it.
>bf00aa4b-05bc-49bc-9e12-4350a314308e::DEBUG::2016-03-18 17:25:48,251::resourceManager::652::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'Storage.c1d2e073-fa2e-47a9-8a0c-3ceefad91685', Clearing records.
>bf00aa4b-05bc-49bc-9e12-4350a314308e::DEBUG::2016-03-18 17:25:48,251::task::916::Storage.TaskManager.Task::(_runJobs) Task=`bf00aa4b-05bc-49bc-9e12-4350a314308e`::Task.run: exit - success: result {'uuid': u'81610d39-bca1-4c94-b193-fae83a8a1912'}
>bf00aa4b-05bc-49bc-9e12-4350a314308e::DEBUG::2016-03-18 17:25:48,252::task::993::Storage.TaskManager.Task::(_decref) Task=`bf00aa4b-05bc-49bc-9e12-4350a314308e`::ref 0 aborting False
>bf00aa4b-05bc-49bc-9e12-4350a314308e::DEBUG::2016-03-18 17:25:48,252::threadPool::51::Storage.ThreadPool::(setRunningTask) Number of running tasks: 0
>mailbox.SPMMonitor::DEBUG::2016-03-18 17:25:49,236::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) /usr/bin/taskset --cpu-list 0-1 dd if=/rhev/data-center/acc8b348-81f6-4bf2-9ffe-f1da755bb38d/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000 (cwd None)
>mailbox.SPMMonitor::DEBUG::2016-03-18 17:25:49,267::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0136531 s, 75.0 MB/s\n'; <rc> = 0
>Thread-43::DEBUG::2016-03-18 17:25:50,273::fileSD::173::Storage.Misc.excCmd::(getReadDelay) /usr/bin/taskset --cpu-list 0-1 /usr/bin/dd if=/rhev/data-center/mnt/10.73.194.27:_vol_S3_libvirtauto_yy_nfs1/c1d2e073-fa2e-47a9-8a0c-3ceefad91685/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
>Thread-43::DEBUG::2016-03-18 17:25:50,293::fileSD::173::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n467 bytes (467 B) copied, 0.000933189 s, 500 kB/s\n'; <rc> = 0
>mailbox.SPMMonitor::DEBUG::2016-03-18 17:25:51,286::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) /usr/bin/taskset --cpu-list 0-1 dd if=/rhev/data-center/acc8b348-81f6-4bf2-9ffe-f1da755bb38d/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000 (cwd None)
>mailbox.SPMMonitor::DEBUG::2016-03-18 17:25:51,318::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0136633 s, 74.9 MB/s\n'; <rc> = 0
>mailbox.SPMMonitor::DEBUG::2016-03-18 17:25:53,330::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) /usr/bin/taskset --cpu-list 0-1 dd if=/rhev/data-center/acc8b348-81f6-4bf2-9ffe-f1da755bb38d/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000 (cwd None)
>mailbox.SPMMonitor::DEBUG::2016-03-18 17:25:53,362::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0136974 s, 74.8 MB/s\n'; <rc> = 0
>mailbox.SPMMonitor::DEBUG::2016-03-18 17:25:55,380::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) /usr/bin/taskset --cpu-list 0-1 dd if=/rhev/data-center/acc8b348-81f6-4bf2-9ffe-f1da755bb38d/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000 (cwd None)
>mailbox.SPMMonitor::DEBUG::2016-03-18 17:25:55,411::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0137128 s, 74.7 MB/s\n'; <rc> = 0
>jsonrpc.Executor/7::DEBUG::2016-03-18 17:25:57,194::__init__::503::jsonrpc.JsonRpcServer::(_serveRequest) Calling 'Host.getAllTasksStatuses' in bridge with {}
>jsonrpc.Executor/7::DEBUG::2016-03-18 17:25:57,195::task::595::Storage.TaskManager.Task::(_updateState) Task=`47ca5716-d3d7-479a-8406-127042fa1a12`::moving from state init -> state preparing
>jsonrpc.Executor/7::INFO::2016-03-18 17:25:57,196::logUtils::48::dispatcher::(wrapper) Run and protect: getAllTasksStatuses(spUUID=None, options=None)
>jsonrpc.Executor/7::DEBUG::2016-03-18 17:25:57,196::taskManager::112::Storage.TaskManager::(getAllTasksStatuses) Entry.
>jsonrpc.Executor/7::DEBUG::2016-03-18 17:25:57,196::taskManager::103::Storage.TaskManager::(getTaskStatus) Entry. taskID: bf00aa4b-05bc-49bc-9e12-4350a314308e
>jsonrpc.Executor/7::DEBUG::2016-03-18 17:25:57,196::taskManager::106::Storage.TaskManager::(getTaskStatus) Return. Response: {'code': 0, 'message': '1 jobs completed successfully', 'taskState': 'finished', 'taskResult': 'success', 'taskID': 'bf00aa4b-05bc-49bc-9e12-4350a314308e'}
>jsonrpc.Executor/7::DEBUG::2016-03-18 17:25:57,197::taskManager::123::Storage.TaskManager::(getAllTasksStatuses) Return: {'bf00aa4b-05bc-49bc-9e12-4350a314308e': {'code': 0, 'message': '1 jobs completed successfully', 'taskState': 'finished', 'taskResult': 'success', 'taskID': 'bf00aa4b-05bc-49bc-9e12-4350a314308e'}}
>jsonrpc.Executor/7::INFO::2016-03-18 17:25:57,197::logUtils::51::dispatcher::(wrapper) Run and protect: getAllTasksStatuses, Return response: {'allTasksStatus': {'bf00aa4b-05bc-49bc-9e12-4350a314308e': {'code': 0, 'message': '1 jobs completed successfully', 'taskState': 'finished', 'taskResult': 'success', 'taskID': 'bf00aa4b-05bc-49bc-9e12-4350a314308e'}}}
>jsonrpc.Executor/7::DEBUG::2016-03-18 17:25:57,197::task::1191::Storage.TaskManager.Task::(prepare) Task=`47ca5716-d3d7-479a-8406-127042fa1a12`::finished: {'allTasksStatus': {'bf00aa4b-05bc-49bc-9e12-4350a314308e': {'code': 0, 'message': '1 jobs completed successfully', 'taskState': 'finished', 'taskResult': 'success', 'taskID': 'bf00aa4b-05bc-49bc-9e12-4350a314308e'}}}
>jsonrpc.Executor/7::DEBUG::2016-03-18 17:25:57,197::task::595::Storage.TaskManager.Task::(_updateState) Task=`47ca5716-d3d7-479a-8406-127042fa1a12`::moving from state preparing -> state finished
>jsonrpc.Executor/7::DEBUG::2016-03-18 17:25:57,197::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>jsonrpc.Executor/7::DEBUG::2016-03-18 17:25:57,197::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>jsonrpc.Executor/7::DEBUG::2016-03-18 17:25:57,198::task::993::Storage.TaskManager.Task::(_decref) Task=`47ca5716-d3d7-479a-8406-127042fa1a12`::ref 0 aborting False
>jsonrpc.Executor/7::DEBUG::2016-03-18 17:25:57,198::__init__::533::jsonrpc.JsonRpcServer::(_serveRequest) Return 'Host.getAllTasksStatuses' in bridge with {'bf00aa4b-05bc-49bc-9e12-4350a314308e': {'code': 0, 'message': '1 jobs completed successfully', 'taskState': 'finished', 'taskResult': 'success', 'taskID': 'bf00aa4b-05bc-49bc-9e12-4350a314308e'}}
>mailbox.SPMMonitor::DEBUG::2016-03-18 17:25:57,424::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) /usr/bin/taskset --cpu-list 0-1 dd if=/rhev/data-center/acc8b348-81f6-4bf2-9ffe-f1da755bb38d/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000 (cwd None)
>mailbox.SPMMonitor::DEBUG::2016-03-18 17:25:57,457::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0136887 s, 74.8 MB/s\n'; <rc> = 0
>jsonrpc.Executor/3::DEBUG::2016-03-18 17:25:58,205::__init__::503::jsonrpc.JsonRpcServer::(_serveRequest) Calling 'StoragePool.getSpmStatus' in bridge with {u'storagepoolID': u'acc8b348-81f6-4bf2-9ffe-f1da755bb38d'}
>jsonrpc.Executor/3::DEBUG::2016-03-18 17:25:58,207::task::595::Storage.TaskManager.Task::(_updateState) Task=`12d09791-0c5d-413f-9527-f2a3d4316da2`::moving from state init -> state preparing
>jsonrpc.Executor/3::INFO::2016-03-18 17:25:58,207::logUtils::48::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID=u'acc8b348-81f6-4bf2-9ffe-f1da755bb38d', options=None)
>jsonrpc.Executor/3::INFO::2016-03-18 17:25:58,222::logUtils::51::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 2L}}
>jsonrpc.Executor/3::DEBUG::2016-03-18 17:25:58,223::task::1191::Storage.TaskManager.Task::(prepare) Task=`12d09791-0c5d-413f-9527-f2a3d4316da2`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 2L}}
>jsonrpc.Executor/3::DEBUG::2016-03-18 17:25:58,223::task::595::Storage.TaskManager.Task::(_updateState) Task=`12d09791-0c5d-413f-9527-f2a3d4316da2`::moving from state preparing -> state finished
>jsonrpc.Executor/3::DEBUG::2016-03-18 17:25:58,223::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>jsonrpc.Executor/3::DEBUG::2016-03-18 17:25:58,223::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>jsonrpc.Executor/3::DEBUG::2016-03-18 17:25:58,223::task::993::Storage.TaskManager.Task::(_decref) Task=`12d09791-0c5d-413f-9527-f2a3d4316da2`::ref 0 aborting False
>jsonrpc.Executor/3::DEBUG::2016-03-18 17:25:58,224::__init__::533::jsonrpc.JsonRpcServer::(_serveRequest) Return 'StoragePool.getSpmStatus' in bridge with {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 2L}
>jsonrpc.Executor/2::DEBUG::2016-03-18 17:25:59,231::__init__::503::jsonrpc.JsonRpcServer::(_serveRequest) Calling 'StoragePool.getInfo' in bridge with {u'storagepoolID': u'acc8b348-81f6-4bf2-9ffe-f1da755bb38d'}
>jsonrpc.Executor/2::DEBUG::2016-03-18 17:25:59,232::task::595::Storage.TaskManager.Task::(_updateState) Task=`9de86db7-4c3c-4f4d-9d19-19b126af51a2`::moving from state init -> state preparing
>jsonrpc.Executor/2::INFO::2016-03-18 17:25:59,233::logUtils::48::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID=u'acc8b348-81f6-4bf2-9ffe-f1da755bb38d', options=None)
>jsonrpc.Executor/2::DEBUG::2016-03-18 17:25:59,233::resourceManager::199::Storage.ResourceManager.Request::(__init__) ResName=`Storage.acc8b348-81f6-4bf2-9ffe-f1da755bb38d`ReqID=`79041d07-a3a0-473d-a838-83ebd5cc90fe`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2642' at 'getStoragePoolInfo'
>jsonrpc.Executor/2::DEBUG::2016-03-18 17:25:59,234::resourceManager::545::Storage.ResourceManager::(registerResource) Trying to register resource 'Storage.acc8b348-81f6-4bf2-9ffe-f1da755bb38d' for lock type 'shared'
>jsonrpc.Executor/2::DEBUG::2016-03-18 17:25:59,234::resourceManager::604::Storage.ResourceManager::(registerResource) Resource 'Storage.acc8b348-81f6-4bf2-9ffe-f1da755bb38d' is free. Now locking as 'shared' (1 active user)
>jsonrpc.Executor/2::DEBUG::2016-03-18 17:25:59,234::resourceManager::239::Storage.ResourceManager.Request::(grant) ResName=`Storage.acc8b348-81f6-4bf2-9ffe-f1da755bb38d`ReqID=`79041d07-a3a0-473d-a838-83ebd5cc90fe`::Granted request
>jsonrpc.Executor/2::DEBUG::2016-03-18 17:25:59,235::task::827::Storage.TaskManager.Task::(resourceAcquired) Task=`9de86db7-4c3c-4f4d-9d19-19b126af51a2`::_resourcesAcquired: Storage.acc8b348-81f6-4bf2-9ffe-f1da755bb38d (shared)
>jsonrpc.Executor/2::DEBUG::2016-03-18 17:25:59,235::task::993::Storage.TaskManager.Task::(_decref) Task=`9de86db7-4c3c-4f4d-9d19-19b126af51a2`::ref 1 aborting False
>jsonrpc.Executor/2::INFO::2016-03-18 17:25:59,253::logUtils::51::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'No Description', 'isoprefix': '', 'pool_status': 'connected', 'lver': 2L, 'domains': u'c1d2e073-fa2e-47a9-8a0c-3ceefad91685:Active', 'master_uuid': u'c1d2e073-fa2e-47a9-8a0c-3ceefad91685', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {u'c1d2e073-fa2e-47a9-8a0c-3ceefad91685': {'status': u'Active', 'diskfree': '159249989632', 'isoprefix': '', 'alerts': [], 'disktotal': '322122547200', 'version': 3}}}
>jsonrpc.Executor/2::DEBUG::2016-03-18 17:25:59,253::task::1191::Storage.TaskManager.Task::(prepare) Task=`9de86db7-4c3c-4f4d-9d19-19b126af51a2`::finished: {'info': {'name': 'No Description', 'isoprefix': '', 'pool_status': 'connected', 'lver': 2L, 'domains': u'c1d2e073-fa2e-47a9-8a0c-3ceefad91685:Active', 'master_uuid': u'c1d2e073-fa2e-47a9-8a0c-3ceefad91685', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {u'c1d2e073-fa2e-47a9-8a0c-3ceefad91685': {'status': u'Active', 'diskfree': '159249989632', 'isoprefix': '', 'alerts': [], 'disktotal': '322122547200', 'version': 3}}}
>jsonrpc.Executor/2::DEBUG::2016-03-18 17:25:59,253::task::595::Storage.TaskManager.Task::(_updateState) Task=`9de86db7-4c3c-4f4d-9d19-19b126af51a2`::moving from state preparing -> state finished
>jsonrpc.Executor/2::DEBUG::2016-03-18 17:25:59,254::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {u'Storage.acc8b348-81f6-4bf2-9ffe-f1da755bb38d': < ResourceRef 'Storage.acc8b348-81f6-4bf2-9ffe-f1da755bb38d', isValid: 'True' obj: 'None'>}
>jsonrpc.Executor/2::DEBUG::2016-03-18 17:25:59,254::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>jsonrpc.Executor/2::DEBUG::2016-03-18 17:25:59,254::resourceManager::619::Storage.ResourceManager::(releaseResource) Trying to release resource 'Storage.acc8b348-81f6-4bf2-9ffe-f1da755bb38d'
>jsonrpc.Executor/2::DEBUG::2016-03-18 17:25:59,254::resourceManager::638::Storage.ResourceManager::(releaseResource) Released resource 'Storage.acc8b348-81f6-4bf2-9ffe-f1da755bb38d' (0 active users)
>jsonrpc.Executor/2::DEBUG::2016-03-18 17:25:59,255::resourceManager::644::Storage.ResourceManager::(releaseResource) Resource 'Storage.acc8b348-81f6-4bf2-9ffe-f1da755bb38d' is free, finding out if anyone is waiting for it.
>jsonrpc.Executor/2::DEBUG::2016-03-18 17:25:59,255::resourceManager::652::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'Storage.acc8b348-81f6-4bf2-9ffe-f1da755bb38d', Clearing records.
>jsonrpc.Executor/2::DEBUG::2016-03-18 17:25:59,255::task::993::Storage.TaskManager.Task::(_decref) Task=`9de86db7-4c3c-4f4d-9d19-19b126af51a2`::ref 0 aborting False
>jsonrpc.Executor/2::DEBUG::2016-03-18 17:25:59,256::__init__::533::jsonrpc.JsonRpcServer::(_serveRequest) Return 'StoragePool.getInfo' in bridge with {'info': {'name': 'No Description', 'isoprefix': '', 'pool_status': 'connected', 'lver': 2L, 'domains': u'c1d2e073-fa2e-47a9-8a0c-3ceefad91685:Active', 'master_uuid': u'c1d2e073-fa2e-47a9-8a0c-3ceefad91685', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {u'c1d2e073-fa2e-47a9-8a0c-3ceefad91685': {'status': u'Active', 'diskfree': '159249989632', 'isoprefix': '', 'alerts': [], 'disktotal': '322122547200', 'version': 3}}}
>mailbox.SPMMonitor::DEBUG::2016-03-18 17:25:59,469::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) /usr/bin/taskset --cpu-list 0-1 dd if=/rhev/data-center/acc8b348-81f6-4bf2-9ffe-f1da755bb38d/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000 (cwd None)
>mailbox.SPMMonitor::DEBUG::2016-03-18 17:25:59,501::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0134725 s, 76.0 MB/s\n'; <rc> = 0
>jsonrpc.Executor/4::DEBUG::2016-03-18 17:25:59,717::task::595::Storage.TaskManager.Task::(_updateState) Task=`5db2f683-0f20-4131-8356-2098f2095d45`::moving from state init -> state preparing
>jsonrpc.Executor/4::INFO::2016-03-18 17:25:59,718::logUtils::48::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>jsonrpc.Executor/4::INFO::2016-03-18 17:25:59,718::logUtils::51::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'c1d2e073-fa2e-47a9-8a0c-3ceefad91685': {'code': 0, 'actual': True, 'version': 3, 'acquired': True, 'delay': '0.000933189', 'lastCheck': '9.4', 'valid': True}}
>jsonrpc.Executor/4::DEBUG::2016-03-18 17:25:59,718::task::1191::Storage.TaskManager.Task::(prepare) Task=`5db2f683-0f20-4131-8356-2098f2095d45`::finished: {u'c1d2e073-fa2e-47a9-8a0c-3ceefad91685': {'code': 0, 'actual': True, 'version': 3, 'acquired': True, 'delay': '0.000933189', 'lastCheck': '9.4', 'valid': True}}
>jsonrpc.Executor/4::DEBUG::2016-03-18 17:25:59,718::task::595::Storage.TaskManager.Task::(_updateState) Task=`5db2f683-0f20-4131-8356-2098f2095d45`::moving from state preparing -> state finished
>jsonrpc.Executor/4::DEBUG::2016-03-18 17:25:59,718::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>jsonrpc.Executor/4::DEBUG::2016-03-18 17:25:59,719::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>jsonrpc.Executor/4::DEBUG::2016-03-18 17:25:59,719::task::993::Storage.TaskManager.Task::(_decref) Task=`5db2f683-0f20-4131-8356-2098f2095d45`::ref 0 aborting False
>jsonrpc.Executor/5::DEBUG::2016-03-18 17:25:59,731::__init__::503::jsonrpc.JsonRpcServer::(_serveRequest) Calling 'Volume.getInfo' in bridge with {u'imageID': u'e7e0392e-bcb9-4486-9e41-e163296528f5', u'storagepoolID': u'acc8b348-81f6-4bf2-9ffe-f1da755bb38d', u'volumeID': u'81610d39-bca1-4c94-b193-fae83a8a1912', u'storagedomainID': u'c1d2e073-fa2e-47a9-8a0c-3ceefad91685'}
>jsonrpc.Executor/5::DEBUG::2016-03-18 17:25:59,732::task::595::Storage.TaskManager.Task::(_updateState) Task=`fe021f09-80be-4e4e-9920-97485495735e`::moving from state init -> state preparing
>jsonrpc.Executor/5::INFO::2016-03-18 17:25:59,733::logUtils::48::dispatcher::(wrapper) Run and protect: getVolumeInfo(sdUUID=u'c1d2e073-fa2e-47a9-8a0c-3ceefad91685', spUUID=u'acc8b348-81f6-4bf2-9ffe-f1da755bb38d', imgUUID=u'e7e0392e-bcb9-4486-9e41-e163296528f5', volUUID=u'81610d39-bca1-4c94-b193-fae83a8a1912', options=None)
>jsonrpc.Executor/5::DEBUG::2016-03-18 17:25:59,734::resourceManager::199::Storage.ResourceManager.Request::(__init__) ResName=`Storage.c1d2e073-fa2e-47a9-8a0c-3ceefad91685`ReqID=`a6ea8b84-9e2d-4a4d-928d-f4e91f74fd1e`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3159' at 'getVolumeInfo'
>jsonrpc.Executor/5::DEBUG::2016-03-18 17:25:59,734::resourceManager::545::Storage.ResourceManager::(registerResource) Trying to register resource 'Storage.c1d2e073-fa2e-47a9-8a0c-3ceefad91685' for lock type 'shared'
>jsonrpc.Executor/5::DEBUG::2016-03-18 17:25:59,734::resourceManager::604::Storage.ResourceManager::(registerResource) Resource 'Storage.c1d2e073-fa2e-47a9-8a0c-3ceefad91685' is free. Now locking as 'shared' (1 active user)
>jsonrpc.Executor/5::DEBUG::2016-03-18 17:25:59,735::resourceManager::239::Storage.ResourceManager.Request::(grant) ResName=`Storage.c1d2e073-fa2e-47a9-8a0c-3ceefad91685`ReqID=`a6ea8b84-9e2d-4a4d-928d-f4e91f74fd1e`::Granted request
>jsonrpc.Executor/5::DEBUG::2016-03-18 17:25:59,735::task::827::Storage.TaskManager.Task::(resourceAcquired) Task=`fe021f09-80be-4e4e-9920-97485495735e`::_resourcesAcquired: Storage.c1d2e073-fa2e-47a9-8a0c-3ceefad91685 (shared)
>jsonrpc.Executor/5::DEBUG::2016-03-18 17:25:59,735::task::993::Storage.TaskManager.Task::(_decref) Task=`fe021f09-80be-4e4e-9920-97485495735e`::ref 1 aborting False
>jsonrpc.Executor/5::DEBUG::2016-03-18 17:25:59,737::fileVolume::535::Storage.Volume::(validateVolumePath) validate path for 81610d39-bca1-4c94-b193-fae83a8a1912
>jsonrpc.Executor/5::INFO::2016-03-18 17:25:59,741::volume::909::Storage.Volume::(getInfo) Info request: sdUUID=c1d2e073-fa2e-47a9-8a0c-3ceefad91685 imgUUID=e7e0392e-bcb9-4486-9e41-e163296528f5 volUUID = 81610d39-bca1-4c94-b193-fae83a8a1912 
>jsonrpc.Executor/5::INFO::2016-03-18 17:25:59,753::volume::937::Storage.Volume::(getInfo) c1d2e073-fa2e-47a9-8a0c-3ceefad91685/e7e0392e-bcb9-4486-9e41-e163296528f5/81610d39-bca1-4c94-b193-fae83a8a1912 info is {'status': 'OK', 'domain': 'c1d2e073-fa2e-47a9-8a0c-3ceefad91685', 'voltype': 'LEAF', 'description': '{"DiskAlias":"vm1_Disk1","DiskDescription":""}', 'parent': '00000000-0000-0000-0000-000000000000', 'format': 'RAW', 'image': 'e7e0392e-bcb9-4486-9e41-e163296528f5', 'ctime': '1458293148', 'disktype': '2', 'legality': 'LEGAL', 'mtime': '0', 'apparentsize': '5368709120', 'children': [], 'pool': '', 'capacity': '5368709120', 'uuid': u'81610d39-bca1-4c94-b193-fae83a8a1912', 'truesize': '0', 'type': 'SPARSE'}
>jsonrpc.Executor/5::INFO::2016-03-18 17:25:59,753::logUtils::51::dispatcher::(wrapper) Run and protect: getVolumeInfo, Return response: {'info': {'status': 'OK', 'domain': 'c1d2e073-fa2e-47a9-8a0c-3ceefad91685', 'voltype': 'LEAF', 'description': '{"DiskAlias":"vm1_Disk1","DiskDescription":""}', 'parent': '00000000-0000-0000-0000-000000000000', 'format': 'RAW', 'image': 'e7e0392e-bcb9-4486-9e41-e163296528f5', 'ctime': '1458293148', 'disktype': '2', 'legality': 'LEGAL', 'mtime': '0', 'apparentsize': '5368709120', 'children': [], 'pool': '', 'capacity': '5368709120', 'uuid': u'81610d39-bca1-4c94-b193-fae83a8a1912', 'truesize': '0', 'type': 'SPARSE'}}
>jsonrpc.Executor/5::DEBUG::2016-03-18 17:25:59,753::task::1191::Storage.TaskManager.Task::(prepare) Task=`fe021f09-80be-4e4e-9920-97485495735e`::finished: {'info': {'status': 'OK', 'domain': 'c1d2e073-fa2e-47a9-8a0c-3ceefad91685', 'voltype': 'LEAF', 'description': '{"DiskAlias":"vm1_Disk1","DiskDescription":""}', 'parent': '00000000-0000-0000-0000-000000000000', 'format': 'RAW', 'image': 'e7e0392e-bcb9-4486-9e41-e163296528f5', 'ctime': '1458293148', 'disktype': '2', 'legality': 'LEGAL', 'mtime': '0', 'apparentsize': '5368709120', 'children': [], 'pool': '', 'capacity': '5368709120', 'uuid': u'81610d39-bca1-4c94-b193-fae83a8a1912', 'truesize': '0', 'type': 'SPARSE'}}
>jsonrpc.Executor/5::DEBUG::2016-03-18 17:25:59,753::task::595::Storage.TaskManager.Task::(_updateState) Task=`fe021f09-80be-4e4e-9920-97485495735e`::moving from state preparing -> state finished
>jsonrpc.Executor/5::DEBUG::2016-03-18 17:25:59,754::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {u'Storage.c1d2e073-fa2e-47a9-8a0c-3ceefad91685': < ResourceRef 'Storage.c1d2e073-fa2e-47a9-8a0c-3ceefad91685', isValid: 'True' obj: 'None'>}
>jsonrpc.Executor/5::DEBUG::2016-03-18 17:25:59,754::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>jsonrpc.Executor/5::DEBUG::2016-03-18 17:25:59,754::resourceManager::619::Storage.ResourceManager::(releaseResource) Trying to release resource 'Storage.c1d2e073-fa2e-47a9-8a0c-3ceefad91685'
>jsonrpc.Executor/5::DEBUG::2016-03-18 17:25:59,754::resourceManager::638::Storage.ResourceManager::(releaseResource) Released resource 'Storage.c1d2e073-fa2e-47a9-8a0c-3ceefad91685' (0 active users)
>jsonrpc.Executor/5::DEBUG::2016-03-18 17:25:59,755::resourceManager::644::Storage.ResourceManager::(releaseResource) Resource 'Storage.c1d2e073-fa2e-47a9-8a0c-3ceefad91685' is free, finding out if anyone is waiting for it.
>jsonrpc.Executor/5::DEBUG::2016-03-18 17:25:59,755::resourceManager::652::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'Storage.c1d2e073-fa2e-47a9-8a0c-3ceefad91685', Clearing records.
>jsonrpc.Executor/5::DEBUG::2016-03-18 17:25:59,755::task::993::Storage.TaskManager.Task::(_decref) Task=`fe021f09-80be-4e4e-9920-97485495735e`::ref 0 aborting False
>jsonrpc.Executor/5::DEBUG::2016-03-18 17:25:59,756::__init__::533::jsonrpc.JsonRpcServer::(_serveRequest) Return 'Volume.getInfo' in bridge with {'status': 'OK', 'domain': 'c1d2e073-fa2e-47a9-8a0c-3ceefad91685', 'voltype': 'LEAF', 'description': '{"DiskAlias":"vm1_Disk1","DiskDescription":""}', 'parent': '00000000-0000-0000-0000-000000000000', 'format': 'RAW', 'image': 'e7e0392e-bcb9-4486-9e41-e163296528f5', 'ctime': '1458293148', 'disktype': '2', 'legality': 'LEGAL', 'allocType': 'SPARSE', 'mtime': '0', 'apparentsize': '5368709120', 'children': [], 'pool': '', 'capacity': '5368709120', 'uuid': u'81610d39-bca1-4c94-b193-fae83a8a1912', 'truesize': '0', 'type': 'SPARSE'}
>Thread-43::DEBUG::2016-03-18 17:26:00,301::fileSD::173::Storage.Misc.excCmd::(getReadDelay) /usr/bin/taskset --cpu-list 0-1 /usr/bin/dd if=/rhev/data-center/mnt/10.73.194.27:_vol_S3_libvirtauto_yy_nfs1/c1d2e073-fa2e-47a9-8a0c-3ceefad91685/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
>Thread-43::DEBUG::2016-03-18 17:26:00,319::fileSD::173::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n467 bytes (467 B) copied, 0.000947069 s, 493 kB/s\n'; <rc> = 0
>jsonrpc.Executor/6::DEBUG::2016-03-18 17:26:00,827::__init__::503::jsonrpc.JsonRpcServer::(_serveRequest) Calling 'Task.clear' in bridge with {u'taskID': u'bf00aa4b-05bc-49bc-9e12-4350a314308e'}
>jsonrpc.Executor/6::DEBUG::2016-03-18 17:26:00,828::task::595::Storage.TaskManager.Task::(_updateState) Task=`1c651573-2df9-4d49-bbf3-f726cad18f8f`::moving from state init -> state preparing
>jsonrpc.Executor/6::INFO::2016-03-18 17:26:00,829::logUtils::48::dispatcher::(wrapper) Run and protect: clearTask(taskID=u'bf00aa4b-05bc-49bc-9e12-4350a314308e', spUUID=None, options=None)
>jsonrpc.Executor/6::DEBUG::2016-03-18 17:26:00,829::taskManager::171::Storage.TaskManager::(clearTask) Entry. taskID: bf00aa4b-05bc-49bc-9e12-4350a314308e
>jsonrpc.Executor/6::DEBUG::2016-03-18 17:26:00,847::taskManager::176::Storage.TaskManager::(clearTask) Return.
>jsonrpc.Executor/6::INFO::2016-03-18 17:26:00,847::logUtils::51::dispatcher::(wrapper) Run and protect: clearTask, Return response: None
>jsonrpc.Executor/6::DEBUG::2016-03-18 17:26:00,847::task::1191::Storage.TaskManager.Task::(prepare) Task=`1c651573-2df9-4d49-bbf3-f726cad18f8f`::finished: None
>jsonrpc.Executor/6::DEBUG::2016-03-18 17:26:00,847::task::595::Storage.TaskManager.Task::(_updateState) Task=`1c651573-2df9-4d49-bbf3-f726cad18f8f`::moving from state preparing -> state finished
>jsonrpc.Executor/6::DEBUG::2016-03-18 17:26:00,848::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>jsonrpc.Executor/6::DEBUG::2016-03-18 17:26:00,848::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>jsonrpc.Executor/6::DEBUG::2016-03-18 17:26:00,848::task::993::Storage.TaskManager.Task::(_decref) Task=`1c651573-2df9-4d49-bbf3-f726cad18f8f`::ref 0 aborting False
>jsonrpc.Executor/6::DEBUG::2016-03-18 17:26:00,848::__init__::533::jsonrpc.JsonRpcServer::(_serveRequest) Return 'Task.clear' in bridge with True
>mailbox.SPMMonitor::DEBUG::2016-03-18 17:26:01,514::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) /usr/bin/taskset --cpu-list 0-1 dd if=/rhev/data-center/acc8b348-81f6-4bf2-9ffe-f1da755bb38d/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000 (cwd None)
>mailbox.SPMMonitor::DEBUG::2016-03-18 17:26:01,545::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0134601 s, 76.1 MB/s\n'; <rc> = 0
>Reactor thread::INFO::2016-03-18 17:26:01,729::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:58372
>Reactor thread::DEBUG::2016-03-18 17:26:01,738::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11
>Reactor thread::INFO::2016-03-18 17:26:01,739::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:58372
>Reactor thread::DEBUG::2016-03-18 17:26:01,739::bindingxmlrpc::1297::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 58372)
>BindingXMLRPC::INFO::2016-03-18 17:26:01,740::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:58372
>Thread-75::INFO::2016-03-18 17:26:01,740::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:58372 started
>Thread-75::INFO::2016-03-18 17:26:01,743::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:58372 stopped
>mailbox.SPMMonitor::DEBUG::2016-03-18 17:26:03,563::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) /usr/bin/taskset --cpu-list 0-1 dd if=/rhev/data-center/acc8b348-81f6-4bf2-9ffe-f1da755bb38d/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000 (cwd None)
>mailbox.SPMMonitor::DEBUG::2016-03-18 17:26:03,594::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0135019 s, 75.8 MB/s\n'; <rc> = 0
>mailbox.SPMMonitor::DEBUG::2016-03-18 17:26:05,617::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) /usr/bin/taskset --cpu-list 0-1 dd if=/rhev/data-center/acc8b348-81f6-4bf2-9ffe-f1da755bb38d/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000 (cwd None)
>mailbox.SPMMonitor::DEBUG::2016-03-18 17:26:05,649::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0136456 s, 75.0 MB/s\n'; <rc> = 0
>mailbox.SPMMonitor::DEBUG::2016-03-18 17:26:07,662::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) /usr/bin/taskset --cpu-list 0-1 dd if=/rhev/data-center/acc8b348-81f6-4bf2-9ffe-f1da755bb38d/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000 (cwd None)
>mailbox.SPMMonitor::DEBUG::2016-03-18 17:26:07,693::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0136653 s, 74.9 MB/s\n'; <rc> = 0
>mailbox.SPMMonitor::DEBUG::2016-03-18 17:26:09,706::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) /usr/bin/taskset --cpu-list 0-1 dd if=/rhev/data-center/acc8b348-81f6-4bf2-9ffe-f1da755bb38d/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000 (cwd None)
>jsonrpc.Executor/1::DEBUG::2016-03-18 17:26:09,734::__init__::503::jsonrpc.JsonRpcServer::(_serveRequest) Calling 'StoragePool.getSpmStatus' in bridge with {u'storagepoolID': u'acc8b348-81f6-4bf2-9ffe-f1da755bb38d'}
>jsonrpc.Executor/1::DEBUG::2016-03-18 17:26:09,736::task::595::Storage.TaskManager.Task::(_updateState) Task=`df548ac1-4728-4eb4-8110-ae438e302970`::moving from state init -> state preparing
>jsonrpc.Executor/1::INFO::2016-03-18 17:26:09,736::logUtils::48::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID=u'acc8b348-81f6-4bf2-9ffe-f1da755bb38d', options=None)
>mailbox.SPMMonitor::DEBUG::2016-03-18 17:26:09,742::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0176085 s, 58.2 MB/s\n'; <rc> = 0
>jsonrpc.Executor/1::INFO::2016-03-18 17:26:09,761::logUtils::51::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 2L}}
>jsonrpc.Executor/1::DEBUG::2016-03-18 17:26:09,761::task::1191::Storage.TaskManager.Task::(prepare) Task=`df548ac1-4728-4eb4-8110-ae438e302970`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 2L}}
>jsonrpc.Executor/1::DEBUG::2016-03-18 17:26:09,761::task::595::Storage.TaskManager.Task::(_updateState) Task=`df548ac1-4728-4eb4-8110-ae438e302970`::moving from state preparing -> state finished
>jsonrpc.Executor/1::DEBUG::2016-03-18 17:26:09,761::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>jsonrpc.Executor/1::DEBUG::2016-03-18 17:26:09,762::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>jsonrpc.Executor/1::DEBUG::2016-03-18 17:26:09,762::task::993::Storage.TaskManager.Task::(_decref) Task=`df548ac1-4728-4eb4-8110-ae438e302970`::ref 0 aborting False
>jsonrpc.Executor/1::DEBUG::2016-03-18 17:26:09,762::__init__::533::jsonrpc.JsonRpcServer::(_serveRequest) Return 'StoragePool.getSpmStatus' in bridge with {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 2L}
>jsonrpc.Executor/7::DEBUG::2016-03-18 17:26:10,020::__init__::503::jsonrpc.JsonRpcServer::(_serveRequest) Calling 'VM.create' in bridge with {u'vmParams': {u'acpiEnable': u'true', u'emulatedMachine': u'pc-i440fx-rhel7.2.0', u'vmId': u'ca440cf8-b140-46c1-8658-c2c71d0229cf', u'memGuaranteedSize': 1024, u'transparentHugePages': u'true', u'timeOffset': u'0', u'cpuType': u'Opteron_G1', u'custom': {}, u'smp': u'1', u'guestNumaNodes': [{u'nodeIndex': 0, u'cpus': u'0', u'memory': u'1024'}], u'maxMemSlots': 16, u'vmType': u'kvm', u'spiceSslCipherSuite': u'DEFAULT', u'memSize': 1024, u'smpCoresPerSocket': u'1', u'vmName': u'vm1', u'nice': u'0', u'maxMemSize': 4194304, u'bootMenuEnable': u'false', u'copyPasteEnable': u'true', u'smpThreadsPerCore': u'1', u'smartcardEnable': u'false', u'fileTransferEnable': u'true', u'keyboardLayout': u'en-us', u'kvmEnable': u'true', u'displayNetwork': u'ovirtmgmt', u'devices': [{u'device': u'qxl', u'specParams': {u'vram': u'8192', u'ram': u'65536', u'heads': u'1', u'vgamem': u'16384'}, u'type': u'video', u'deviceId': u'1245228b-332e-4678-890b-78010aa775e2'}, {u'device': u'spice', u'specParams': {u'fileTransferEnable': u'true', u'copyPasteEnable': u'true'}, u'type': u'graphics', u'deviceId': u'5e38528d-f474-4a71-a1f2-ee58a2b1376d'}, {u'index': u'2', u'iface': u'ide', u'specParams': {u'path': u''}, u'readonly': u'true', u'deviceId': u'4ff576a1-93f2-451e-a220-151a30c2c636', u'path': u'', u'device': u'cdrom', u'shared': u'false', u'type': u'disk'}, {u'index': 0, u'iface': u'virtio', u'format': u'raw', u'bootOrder': u'2', u'volumeID': u'81610d39-bca1-4c94-b193-fae83a8a1912', u'imageID': u'e7e0392e-bcb9-4486-9e41-e163296528f5', u'specParams': {}, u'readonly': u'false', u'domainID': u'c1d2e073-fa2e-47a9-8a0c-3ceefad91685', u'optional': u'false', u'deviceId': u'e7e0392e-bcb9-4486-9e41-e163296528f5', u'poolID': u'acc8b348-81f6-4bf2-9ffe-f1da755bb38d', u'device': u'disk', u'shared': u'false', u'propagateErrors': u'off', u'type': u'disk'}, {u'nicModel': u'pv', u'macAddr': u'00:1a:4a:16:01:51', u'linkActive': u'true', u'network': u'ovirtmgmt', u'bootOrder': u'1', u'filter': u'vdsm-no-mac-spoofing', u'specParams': {u'inbound': {}, u'outbound': {}}, u'deviceId': u'2d1be0ea-ec38-4f63-a42c-e4bee0d02d2e', u'device': u'bridge', u'type': u'interface'}, {u'device': u'memballoon', u'specParams': {u'model': u'virtio'}, u'type': u'balloon', u'deviceId': u'cacda659-c0fd-4a88-9eac-e9fbfc4f9e94'}, {u'index': u'0', u'specParams': {}, u'deviceId': u'390b4cc9-f824-4be8-b3ba-04f05045e90d', u'device': u'scsi', u'model': u'virtio-scsi', u'type': u'controller'}, {u'device': u'virtio-serial', u'specParams': {}, u'type': u'controller', u'deviceId': u'1a747327-a65f-4b7b-9530-e60a90e6c715'}], u'maxVCpus': u'16', u'spiceSecureChannels': u'smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard', u'display': u'qxl'}, u'vmID': u'ca440cf8-b140-46c1-8658-c2c71d0229cf'}
>jsonrpc.Executor/3::DEBUG::2016-03-18 17:26:10,023::__init__::503::jsonrpc.JsonRpcServer::(_serveRequest) Calling 'StoragePool.getInfo' in bridge with {u'storagepoolID': u'acc8b348-81f6-4bf2-9ffe-f1da755bb38d'}
>jsonrpc.Executor/3::DEBUG::2016-03-18 17:26:10,024::task::595::Storage.TaskManager.Task::(_updateState) Task=`8e8012e7-934f-4d5d-9724-01efa09b2a90`::moving from state init -> state preparing
>jsonrpc.Executor/3::INFO::2016-03-18 17:26:10,024::logUtils::48::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID=u'acc8b348-81f6-4bf2-9ffe-f1da755bb38d', options=None)
>jsonrpc.Executor/3::DEBUG::2016-03-18 17:26:10,025::resourceManager::199::Storage.ResourceManager.Request::(__init__) ResName=`Storage.acc8b348-81f6-4bf2-9ffe-f1da755bb38d`ReqID=`71a4c958-cb12-4dda-ab24-1ddfcc52b684`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2642' at 'getStoragePoolInfo'
>jsonrpc.Executor/3::DEBUG::2016-03-18 17:26:10,026::resourceManager::545::Storage.ResourceManager::(registerResource) Trying to register resource 'Storage.acc8b348-81f6-4bf2-9ffe-f1da755bb38d' for lock type 'shared'
>jsonrpc.Executor/3::DEBUG::2016-03-18 17:26:10,026::resourceManager::604::Storage.ResourceManager::(registerResource) Resource 'Storage.acc8b348-81f6-4bf2-9ffe-f1da755bb38d' is free. Now locking as 'shared' (1 active user)
>jsonrpc.Executor/3::DEBUG::2016-03-18 17:26:10,026::resourceManager::239::Storage.ResourceManager.Request::(grant) ResName=`Storage.acc8b348-81f6-4bf2-9ffe-f1da755bb38d`ReqID=`71a4c958-cb12-4dda-ab24-1ddfcc52b684`::Granted request
>jsonrpc.Executor/3::DEBUG::2016-03-18 17:26:10,027::task::827::Storage.TaskManager.Task::(resourceAcquired) Task=`8e8012e7-934f-4d5d-9724-01efa09b2a90`::_resourcesAcquired: Storage.acc8b348-81f6-4bf2-9ffe-f1da755bb38d (shared)
>jsonrpc.Executor/3::DEBUG::2016-03-18 17:26:10,027::task::993::Storage.TaskManager.Task::(_decref) Task=`8e8012e7-934f-4d5d-9724-01efa09b2a90`::ref 1 aborting False
>jsonrpc.Executor/7::DEBUG::2016-03-18 17:26:10,042::__init__::533::jsonrpc.JsonRpcServer::(_serveRequest) Return 'VM.create' in bridge with {u'acpiEnable': u'true', u'emulatedMachine': u'pc-i440fx-rhel7.2.0', 'pid': '0', u'memGuaranteedSize': 1024, u'transparentHugePages': u'true', 'displayPort': '-1', 'displaySecurePort': '-1', u'spiceSslCipherSuite': u'DEFAULT', u'cpuType': u'Opteron_G1', u'smp': u'1', u'guestNumaNodes': [{u'nodeIndex': 0, u'cpus': u'0', u'memory': u'1024'}], u'smartcardEnable': u'false', u'custom': {}, u'vmType': u'kvm', u'memSize': 1024, u'smpCoresPerSocket': u'1', u'vmName': u'vm1', u'nice': u'0', 'status': 'WaitForLaunch', u'maxMemSize': 4194304, u'bootMenuEnable': u'false', u'vmId': u'ca440cf8-b140-46c1-8658-c2c71d0229cf', u'copyPasteEnable': u'true', 'displayIp': '10.66.83.177', u'smpThreadsPerCore': u'1', 'guestDiskMapping': {}, u'spiceSecureChannels': u'smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard', u'fileTransferEnable': u'true', 'nicModel': 'rtl8139,pv', u'keyboardLayout': u'en-us', u'kvmEnable': u'true', u'displayNetwork': u'ovirtmgmt', u'devices': [{u'device': u'qxl', u'specParams': {u'vram': u'8192', u'ram': u'65536', u'heads': u'1', u'vgamem': u'16384'}, 'deviceType': u'video', u'type': u'video', u'deviceId': u'1245228b-332e-4678-890b-78010aa775e2'}, {u'device': u'spice', u'specParams': {u'fileTransferEnable': u'true', u'copyPasteEnable': u'true'}, 'deviceType': u'graphics', u'type': u'graphics', u'deviceId': u'5e38528d-f474-4a71-a1f2-ee58a2b1376d'}, {u'index': u'2', u'iface': u'ide', u'specParams': {u'path': u''}, u'readonly': u'true', 'deviceType': u'disk', u'deviceId': u'4ff576a1-93f2-451e-a220-151a30c2c636', u'shared': u'false', u'device': u'cdrom', u'path': u'', u'type': u'disk'}, {u'index': 0, u'iface': u'virtio', u'type': u'disk', u'format': u'raw', u'bootOrder': u'2', u'volumeID': u'81610d39-bca1-4c94-b193-fae83a8a1912', u'imageID': u'e7e0392e-bcb9-4486-9e41-e163296528f5', u'specParams': {}, u'readonly': u'false', u'domainID': u'c1d2e073-fa2e-47a9-8a0c-3ceefad91685', 'deviceType': u'disk', u'deviceId': u'e7e0392e-bcb9-4486-9e41-e163296528f5', u'poolID': u'acc8b348-81f6-4bf2-9ffe-f1da755bb38d', u'device': u'disk', u'shared': u'false', u'propagateErrors': u'off', u'optional': u'false'}, {u'nicModel': u'pv', u'macAddr': u'00:1a:4a:16:01:51', u'linkActive': u'true', u'network': u'ovirtmgmt', u'bootOrder': u'1', u'filter': u'vdsm-no-mac-spoofing', u'specParams': {u'inbound': {}, u'outbound': {}}, 'deviceType': u'interface', u'deviceId': u'2d1be0ea-ec38-4f63-a42c-e4bee0d02d2e', u'device': u'bridge', u'type': u'interface'}, {u'device': u'memballoon', u'specParams': {u'model': u'virtio'}, 'deviceType': u'balloon', u'type': u'balloon', u'deviceId': u'cacda659-c0fd-4a88-9eac-e9fbfc4f9e94'}, {u'index': u'0', u'specParams': {}, 'deviceType': u'controller', u'deviceId': u'390b4cc9-f824-4be8-b3ba-04f05045e90d', u'device': u'scsi', u'model': u'virtio-scsi', u'type': u'controller'}, {u'device': u'virtio-serial', u'specParams': {}, 'deviceType': u'controller', u'type': u'controller', u'deviceId': u'1a747327-a65f-4b7b-9530-e60a90e6c715'}], u'display': 'qxl', u'timeOffset': u'0', u'maxVCpus': u'16', 'clientIp': '', 'statusTime': '4388290710', u'maxMemSlots': 16}
>Thread-76::DEBUG::2016-03-18 17:26:10,045::vm::697::virt.vm::(_startUnderlyingVm) vmId=`ca440cf8-b140-46c1-8658-c2c71d0229cf`::Start
>Thread-76::INFO::2016-03-18 17:26:10,045::vm::1850::virt.vm::(_run) vmId=`ca440cf8-b140-46c1-8658-c2c71d0229cf`::VM wrapper has started
>Thread-76::DEBUG::2016-03-18 17:26:10,046::task::595::Storage.TaskManager.Task::(_updateState) Task=`4d75d6e6-ae3a-4c4a-8f3b-ef428d9343c1`::moving from state init -> state preparing
>Thread-76::INFO::2016-03-18 17:26:10,046::logUtils::48::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID=u'c1d2e073-fa2e-47a9-8a0c-3ceefad91685', spUUID=u'acc8b348-81f6-4bf2-9ffe-f1da755bb38d', imgUUID=u'e7e0392e-bcb9-4486-9e41-e163296528f5', volUUID=u'81610d39-bca1-4c94-b193-fae83a8a1912', options=None)
>jsonrpc.Executor/3::INFO::2016-03-18 17:26:10,052::logUtils::51::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'No Description', 'isoprefix': '', 'pool_status': 'connected', 'lver': 2L, 'domains': u'c1d2e073-fa2e-47a9-8a0c-3ceefad91685:Active', 'master_uuid': u'c1d2e073-fa2e-47a9-8a0c-3ceefad91685', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {u'c1d2e073-fa2e-47a9-8a0c-3ceefad91685': {'status': u'Active', 'diskfree': '159249989632', 'isoprefix': '', 'alerts': [], 'disktotal': '322122547200', 'version': 3}}}
>jsonrpc.Executor/3::DEBUG::2016-03-18 17:26:10,053::task::1191::Storage.TaskManager.Task::(prepare) Task=`8e8012e7-934f-4d5d-9724-01efa09b2a90`::finished: {'info': {'name': 'No Description', 'isoprefix': '', 'pool_status': 'connected', 'lver': 2L, 'domains': u'c1d2e073-fa2e-47a9-8a0c-3ceefad91685:Active', 'master_uuid': u'c1d2e073-fa2e-47a9-8a0c-3ceefad91685', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {u'c1d2e073-fa2e-47a9-8a0c-3ceefad91685': {'status': u'Active', 'diskfree': '159249989632', 'isoprefix': '', 'alerts': [], 'disktotal': '322122547200', 'version': 3}}}
>jsonrpc.Executor/3::DEBUG::2016-03-18 17:26:10,053::task::595::Storage.TaskManager.Task::(_updateState) Task=`8e8012e7-934f-4d5d-9724-01efa09b2a90`::moving from state preparing -> state finished
>jsonrpc.Executor/3::DEBUG::2016-03-18 17:26:10,053::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {u'Storage.acc8b348-81f6-4bf2-9ffe-f1da755bb38d': < ResourceRef 'Storage.acc8b348-81f6-4bf2-9ffe-f1da755bb38d', isValid: 'True' obj: 'None'>}
>jsonrpc.Executor/3::DEBUG::2016-03-18 17:26:10,053::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>jsonrpc.Executor/3::DEBUG::2016-03-18 17:26:10,054::resourceManager::619::Storage.ResourceManager::(releaseResource) Trying to release resource 'Storage.acc8b348-81f6-4bf2-9ffe-f1da755bb38d'
>jsonrpc.Executor/3::DEBUG::2016-03-18 17:26:10,054::resourceManager::638::Storage.ResourceManager::(releaseResource) Released resource 'Storage.acc8b348-81f6-4bf2-9ffe-f1da755bb38d' (0 active users)
>jsonrpc.Executor/3::DEBUG::2016-03-18 17:26:10,054::resourceManager::644::Storage.ResourceManager::(releaseResource) Resource 'Storage.acc8b348-81f6-4bf2-9ffe-f1da755bb38d' is free, finding out if anyone is waiting for it.
>jsonrpc.Executor/3::DEBUG::2016-03-18 17:26:10,054::resourceManager::652::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'Storage.acc8b348-81f6-4bf2-9ffe-f1da755bb38d', Clearing records.
>jsonrpc.Executor/3::DEBUG::2016-03-18 17:26:10,055::task::993::Storage.TaskManager.Task::(_decref) Task=`8e8012e7-934f-4d5d-9724-01efa09b2a90`::ref 0 aborting False
>jsonrpc.Executor/3::DEBUG::2016-03-18 17:26:10,055::__init__::533::jsonrpc.JsonRpcServer::(_serveRequest) Return 'StoragePool.getInfo' in bridge with {'info': {'name': 'No Description', 'isoprefix': '', 'pool_status': 'connected', 'lver': 2L, 'domains': u'c1d2e073-fa2e-47a9-8a0c-3ceefad91685:Active', 'master_uuid': u'c1d2e073-fa2e-47a9-8a0c-3ceefad91685', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {u'c1d2e073-fa2e-47a9-8a0c-3ceefad91685': {'status': u'Active', 'diskfree': '159249989632', 'isoprefix': '', 'alerts': [], 'disktotal': '322122547200', 'version': 3}}}
>Thread-76::INFO::2016-03-18 17:26:10,058::logUtils::51::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '0', 'apparentsize': '5368709120'}
>Thread-76::DEBUG::2016-03-18 17:26:10,058::task::1191::Storage.TaskManager.Task::(prepare) Task=`4d75d6e6-ae3a-4c4a-8f3b-ef428d9343c1`::finished: {'truesize': '0', 'apparentsize': '5368709120'}
>Thread-76::DEBUG::2016-03-18 17:26:10,058::task::595::Storage.TaskManager.Task::(_updateState) Task=`4d75d6e6-ae3a-4c4a-8f3b-ef428d9343c1`::moving from state preparing -> state finished
>Thread-76::DEBUG::2016-03-18 17:26:10,058::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-76::DEBUG::2016-03-18 17:26:10,059::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-76::DEBUG::2016-03-18 17:26:10,059::task::993::Storage.TaskManager.Task::(_decref) Task=`4d75d6e6-ae3a-4c4a-8f3b-ef428d9343c1`::ref 0 aborting False
>Thread-76::INFO::2016-03-18 17:26:10,059::clientIF::375::vds::(prepareVolumePath) prepared volume path: 
>Thread-76::DEBUG::2016-03-18 17:26:10,060::task::595::Storage.TaskManager.Task::(_updateState) Task=`17d84148-7cd6-4f6f-9733-5d06e215541f`::moving from state init -> state preparing
>Thread-76::INFO::2016-03-18 17:26:10,060::logUtils::48::dispatcher::(wrapper) Run and protect: prepareImage(sdUUID=u'c1d2e073-fa2e-47a9-8a0c-3ceefad91685', spUUID=u'acc8b348-81f6-4bf2-9ffe-f1da755bb38d', imgUUID=u'e7e0392e-bcb9-4486-9e41-e163296528f5', leafUUID=u'81610d39-bca1-4c94-b193-fae83a8a1912')
>Thread-76::DEBUG::2016-03-18 17:26:10,061::resourceManager::199::Storage.ResourceManager.Request::(__init__) ResName=`Storage.c1d2e073-fa2e-47a9-8a0c-3ceefad91685`ReqID=`6c45ca0f-e6fd-4af4-aff8-4268290b9739`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3213' at 'prepareImage'
>Thread-76::DEBUG::2016-03-18 17:26:10,061::resourceManager::545::Storage.ResourceManager::(registerResource) Trying to register resource 'Storage.c1d2e073-fa2e-47a9-8a0c-3ceefad91685' for lock type 'shared'
>Thread-76::DEBUG::2016-03-18 17:26:10,061::resourceManager::604::Storage.ResourceManager::(registerResource) Resource 'Storage.c1d2e073-fa2e-47a9-8a0c-3ceefad91685' is free. Now locking as 'shared' (1 active user)
>Thread-76::DEBUG::2016-03-18 17:26:10,062::resourceManager::239::Storage.ResourceManager.Request::(grant) ResName=`Storage.c1d2e073-fa2e-47a9-8a0c-3ceefad91685`ReqID=`6c45ca0f-e6fd-4af4-aff8-4268290b9739`::Granted request
>Thread-76::DEBUG::2016-03-18 17:26:10,062::task::827::Storage.TaskManager.Task::(resourceAcquired) Task=`17d84148-7cd6-4f6f-9733-5d06e215541f`::_resourcesAcquired: Storage.c1d2e073-fa2e-47a9-8a0c-3ceefad91685 (shared)
>Thread-76::DEBUG::2016-03-18 17:26:10,062::task::993::Storage.TaskManager.Task::(_decref) Task=`17d84148-7cd6-4f6f-9733-5d06e215541f`::ref 1 aborting False
>Thread-76::DEBUG::2016-03-18 17:26:10,067::fileSD::556::Storage.StorageDomain::(activateVolumes) Fixing permissions on /rhev/data-center/mnt/10.73.194.27:_vol_S3_libvirtauto_yy_nfs1/c1d2e073-fa2e-47a9-8a0c-3ceefad91685/images/e7e0392e-bcb9-4486-9e41-e163296528f5/81610d39-bca1-4c94-b193-fae83a8a1912
>Thread-76::DEBUG::2016-03-18 17:26:10,068::fileUtils::143::Storage.fileUtils::(createdir) Creating directory: /var/run/vdsm/storage/c1d2e073-fa2e-47a9-8a0c-3ceefad91685 mode: None
>Thread-76::DEBUG::2016-03-18 17:26:10,068::fileSD::513::Storage.StorageDomain::(createImageLinks) Creating symlink from /rhev/data-center/mnt/10.73.194.27:_vol_S3_libvirtauto_yy_nfs1/c1d2e073-fa2e-47a9-8a0c-3ceefad91685/images/e7e0392e-bcb9-4486-9e41-e163296528f5 to /var/run/vdsm/storage/c1d2e073-fa2e-47a9-8a0c-3ceefad91685/e7e0392e-bcb9-4486-9e41-e163296528f5
>Thread-76::DEBUG::2016-03-18 17:26:10,071::fileVolume::535::Storage.Volume::(validateVolumePath) validate path for 81610d39-bca1-4c94-b193-fae83a8a1912
>Thread-76::INFO::2016-03-18 17:26:10,074::logUtils::51::dispatcher::(wrapper) Run and protect: prepareImage, Return response: {'info': {'domainID': u'c1d2e073-fa2e-47a9-8a0c-3ceefad91685', 'volType': 'path', 'leaseOffset': 0, 'path': u'/rhev/data-center/mnt/10.73.194.27:_vol_S3_libvirtauto_yy_nfs1/c1d2e073-fa2e-47a9-8a0c-3ceefad91685/images/e7e0392e-bcb9-4486-9e41-e163296528f5/81610d39-bca1-4c94-b193-fae83a8a1912', 'volumeID': u'81610d39-bca1-4c94-b193-fae83a8a1912', 'leasePath': u'/rhev/data-center/mnt/10.73.194.27:_vol_S3_libvirtauto_yy_nfs1/c1d2e073-fa2e-47a9-8a0c-3ceefad91685/images/e7e0392e-bcb9-4486-9e41-e163296528f5/81610d39-bca1-4c94-b193-fae83a8a1912.lease', 'imageID': u'e7e0392e-bcb9-4486-9e41-e163296528f5'}, 'path': u'/rhev/data-center/acc8b348-81f6-4bf2-9ffe-f1da755bb38d/c1d2e073-fa2e-47a9-8a0c-3ceefad91685/images/e7e0392e-bcb9-4486-9e41-e163296528f5/81610d39-bca1-4c94-b193-fae83a8a1912', 'imgVolumesInfo': [{'domainID': u'c1d2e073-fa2e-47a9-8a0c-3ceefad91685', 'volType': 'path', 'leaseOffset': 0, 'path': u'/rhev/data-center/mnt/10.73.194.27:_vol_S3_libvirtauto_yy_nfs1/c1d2e073-fa2e-47a9-8a0c-3ceefad91685/images/e7e0392e-bcb9-4486-9e41-e163296528f5/81610d39-bca1-4c94-b193-fae83a8a1912', 'volumeID': u'81610d39-bca1-4c94-b193-fae83a8a1912', 'leasePath': u'/rhev/data-center/mnt/10.73.194.27:_vol_S3_libvirtauto_yy_nfs1/c1d2e073-fa2e-47a9-8a0c-3ceefad91685/images/e7e0392e-bcb9-4486-9e41-e163296528f5/81610d39-bca1-4c94-b193-fae83a8a1912.lease', 'imageID': u'e7e0392e-bcb9-4486-9e41-e163296528f5'}]}
>Thread-76::DEBUG::2016-03-18 17:26:10,074::task::1191::Storage.TaskManager.Task::(prepare) Task=`17d84148-7cd6-4f6f-9733-5d06e215541f`::finished: {'info': {'domainID': u'c1d2e073-fa2e-47a9-8a0c-3ceefad91685', 'volType': 'path', 'leaseOffset': 0, 'path': u'/rhev/data-center/mnt/10.73.194.27:_vol_S3_libvirtauto_yy_nfs1/c1d2e073-fa2e-47a9-8a0c-3ceefad91685/images/e7e0392e-bcb9-4486-9e41-e163296528f5/81610d39-bca1-4c94-b193-fae83a8a1912', 'volumeID': u'81610d39-bca1-4c94-b193-fae83a8a1912', 'leasePath': u'/rhev/data-center/mnt/10.73.194.27:_vol_S3_libvirtauto_yy_nfs1/c1d2e073-fa2e-47a9-8a0c-3ceefad91685/images/e7e0392e-bcb9-4486-9e41-e163296528f5/81610d39-bca1-4c94-b193-fae83a8a1912.lease', 'imageID': u'e7e0392e-bcb9-4486-9e41-e163296528f5'}, 'path': u'/rhev/data-center/acc8b348-81f6-4bf2-9ffe-f1da755bb38d/c1d2e073-fa2e-47a9-8a0c-3ceefad91685/images/e7e0392e-bcb9-4486-9e41-e163296528f5/81610d39-bca1-4c94-b193-fae83a8a1912', 'imgVolumesInfo': [{'domainID': u'c1d2e073-fa2e-47a9-8a0c-3ceefad91685', 'volType': 'path', 'leaseOffset': 0, 'path': u'/rhev/data-center/mnt/10.73.194.27:_vol_S3_libvirtauto_yy_nfs1/c1d2e073-fa2e-47a9-8a0c-3ceefad91685/images/e7e0392e-bcb9-4486-9e41-e163296528f5/81610d39-bca1-4c94-b193-fae83a8a1912', 'volumeID': u'81610d39-bca1-4c94-b193-fae83a8a1912', 'leasePath': u'/rhev/data-center/mnt/10.73.194.27:_vol_S3_libvirtauto_yy_nfs1/c1d2e073-fa2e-47a9-8a0c-3ceefad91685/images/e7e0392e-bcb9-4486-9e41-e163296528f5/81610d39-bca1-4c94-b193-fae83a8a1912.lease', 'imageID': u'e7e0392e-bcb9-4486-9e41-e163296528f5'}]}
>Thread-76::DEBUG::2016-03-18 17:26:10,075::task::595::Storage.TaskManager.Task::(_updateState) Task=`17d84148-7cd6-4f6f-9733-5d06e215541f`::moving from state preparing -> state finished
>Thread-76::DEBUG::2016-03-18 17:26:10,075::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {u'Storage.c1d2e073-fa2e-47a9-8a0c-3ceefad91685': < ResourceRef 'Storage.c1d2e073-fa2e-47a9-8a0c-3ceefad91685', isValid: 'True' obj: 'None'>}
>Thread-76::DEBUG::2016-03-18 17:26:10,075::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-76::DEBUG::2016-03-18 17:26:10,075::resourceManager::619::Storage.ResourceManager::(releaseResource) Trying to release resource 'Storage.c1d2e073-fa2e-47a9-8a0c-3ceefad91685'
>Thread-76::DEBUG::2016-03-18 17:26:10,076::resourceManager::638::Storage.ResourceManager::(releaseResource) Released resource 'Storage.c1d2e073-fa2e-47a9-8a0c-3ceefad91685' (0 active users)
>Thread-76::DEBUG::2016-03-18 17:26:10,076::resourceManager::644::Storage.ResourceManager::(releaseResource) Resource 'Storage.c1d2e073-fa2e-47a9-8a0c-3ceefad91685' is free, finding out if anyone is waiting for it.
>Thread-76::DEBUG::2016-03-18 17:26:10,076::resourceManager::652::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'Storage.c1d2e073-fa2e-47a9-8a0c-3ceefad91685', Clearing records.
>Thread-76::DEBUG::2016-03-18 17:26:10,076::task::993::Storage.TaskManager.Task::(_decref) Task=`17d84148-7cd6-4f6f-9733-5d06e215541f`::ref 0 aborting False
>Thread-76::INFO::2016-03-18 17:26:10,077::clientIF::375::vds::(prepareVolumePath) prepared volume path: /rhev/data-center/acc8b348-81f6-4bf2-9ffe-f1da755bb38d/c1d2e073-fa2e-47a9-8a0c-3ceefad91685/images/e7e0392e-bcb9-4486-9e41-e163296528f5/81610d39-bca1-4c94-b193-fae83a8a1912
>Thread-76::DEBUG::2016-03-18 17:26:10,085::core::51::virt.vm::(__init__) vmId=`ca440cf8-b140-46c1-8658-c2c71d0229cf`::Ignoring param (target, 1048576) in Balloon
>Thread-76::INFO::2016-03-18 17:26:10,146::vm::1932::virt.vm::(_run) vmId=`ca440cf8-b140-46c1-8658-c2c71d0229cf`::<?xml version="1.0" encoding="utf-8"?>
><domain type="kvm" xmlns:ovirt="http://ovirt.org/vm/tune/1.0">
>	<name>vm1</name>
>	<uuid>ca440cf8-b140-46c1-8658-c2c71d0229cf</uuid>
>	<memory>1048576</memory>
>	<currentMemory>1048576</currentMemory>
>	<maxMemory slots="16">4294967296</maxMemory>
>	<vcpu current="1">16</vcpu>
>	<devices>
>		<channel type="unix">
>			<target name="com.redhat.rhevm.vdsm" type="virtio"/>
>			<source mode="bind" path="/var/lib/libvirt/qemu/channels/ca440cf8-b140-46c1-8658-c2c71d0229cf.com.redhat.rhevm.vdsm"/>
>		</channel>
>		<channel type="unix">
>			<target name="org.qemu.guest_agent.0" type="virtio"/>
>			<source mode="bind" path="/var/lib/libvirt/qemu/channels/ca440cf8-b140-46c1-8658-c2c71d0229cf.org.qemu.guest_agent.0"/>
>		</channel>
>		<input bus="ps2" type="mouse"/>
>		<memballoon model="virtio"/>
>		<controller index="0" model="virtio-scsi" type="scsi"/>
>		<controller index="0" ports="16" type="virtio-serial"/>
>		<video>
>			<model heads="1" ram="65536" type="qxl" vgamem="16384" vram="8192"/>
>		</video>
>		<graphics autoport="yes" passwd="*****" passwdValidTo="1970-01-01T00:00:01" port="-1" tlsPort="-1" type="spice">
>			<listen network="vdsm-ovirtmgmt" type="network"/>
>		</graphics>
>		<interface type="bridge">
>			<mac address="00:1a:4a:16:01:51"/>
>			<model type="virtio"/>
>			<source bridge="ovirtmgmt"/>
>			<filterref filter="vdsm-no-mac-spoofing"/>
>			<link state="up"/>
>			<boot order="1"/>
>			<bandwidth/>
>		</interface>
>		<disk device="cdrom" snapshot="no" type="file">
>			<source file="" startupPolicy="optional"/>
>			<target bus="ide" dev="hdc"/>
>			<readonly/>
>			<serial/>
>		</disk>
>		<disk device="disk" snapshot="no" type="file">
>			<source file="/rhev/data-center/acc8b348-81f6-4bf2-9ffe-f1da755bb38d/c1d2e073-fa2e-47a9-8a0c-3ceefad91685/images/e7e0392e-bcb9-4486-9e41-e163296528f5/81610d39-bca1-4c94-b193-fae83a8a1912"/>
>			<target bus="virtio" dev="vda"/>
>			<serial>e7e0392e-bcb9-4486-9e41-e163296528f5</serial>
>			<boot order="2"/>
>			<driver cache="none" error_policy="stop" io="threads" name="qemu" type="raw"/>
>		</disk>
>		<channel type="spicevmc">
>			<target name="com.redhat.spice.0" type="virtio"/>
>		</channel>
>	</devices>
>	<metadata>
>		<ovirt:qos/>
>	</metadata>
>	<os>
>		<type arch="x86_64" machine="pc-i440fx-rhel7.2.0">hvm</type>
>		<smbios mode="sysinfo"/>
>	</os>
>	<sysinfo type="smbios">
>		<system>
>			<entry name="manufacturer">Red Hat</entry>
>			<entry name="product">RHEV Hypervisor</entry>
>			<entry name="version">7.3-2.el7</entry>
>			<entry name="serial">44454C4C-5700-1038-8047-B3C04F4D3258</entry>
>			<entry name="uuid">ca440cf8-b140-46c1-8658-c2c71d0229cf</entry>
>		</system>
>	</sysinfo>
>	<clock adjustment="0" offset="variable">
>		<timer name="rtc" tickpolicy="catchup"/>
>		<timer name="pit" tickpolicy="delay"/>
>		<timer name="hpet" present="no"/>
>	</clock>
>	<features>
>		<acpi/>
>	</features>
>	<cpu match="exact">
>		<model>Opteron_G1</model>
>		<topology cores="1" sockets="16" threads="1"/>
>		<numa>
>			<cell cpus="0" memory="1048576"/>
>		</numa>
>	</cpu>
></domain>
>
>periodic/1::WARNING::2016-03-18 17:26:10,214::periodic::258::virt.periodic.VmDispatcher::(__call__) could not run <class 'virt.periodic.DriveWatermarkMonitor'> on [u'ca440cf8-b140-46c1-8658-c2c71d0229cf']
>Thread-43::DEBUG::2016-03-18 17:26:10,330::fileSD::173::Storage.Misc.excCmd::(getReadDelay) /usr/bin/taskset --cpu-list 0-1 /usr/bin/dd if=/rhev/data-center/mnt/10.73.194.27:_vol_S3_libvirtauto_yy_nfs1/c1d2e073-fa2e-47a9-8a0c-3ceefad91685/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
>Thread-43::DEBUG::2016-03-18 17:26:10,350::fileSD::173::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n467 bytes (467 B) copied, 0.00101759 s, 459 kB/s\n'; <rc> = 0
>libvirtEventLoop::DEBUG::2016-03-18 17:26:11,565::vm::4563::virt.vm::(onLibvirtLifecycleEvent) vmId=`ca440cf8-b140-46c1-8658-c2c71d0229cf`::event Resumed detail 0 opaque None
>libvirtEventLoop::INFO::2016-03-18 17:26:11,566::vm::5084::virt.vm::(_logGuestCpuStatus) vmId=`ca440cf8-b140-46c1-8658-c2c71d0229cf`::CPU running: onResume
>libvirtEventLoop::DEBUG::2016-03-18 17:26:11,584::vm::4563::virt.vm::(onLibvirtLifecycleEvent) vmId=`ca440cf8-b140-46c1-8658-c2c71d0229cf`::event Started detail 0 opaque None
>Thread-76::DEBUG::2016-03-18 17:26:11,622::vm::4358::virt.vm::(_getUnderlyingDriveInfo) vmId=`ca440cf8-b140-46c1-8658-c2c71d0229cf`::Looking for drive with attributes {'name': u'hdc', 'bootOrder': '', 'boot': [], 'readonly': True, 'address': {u'bus': u'1', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'0'}, 'path': '', 'type': u'cdrom'}
>Thread-76::DEBUG::2016-03-18 17:26:11,623::vm::4379::virt.vm::(_getUnderlyingDriveInfo) vmId=`ca440cf8-b140-46c1-8658-c2c71d0229cf`::Matched {'name': (u'hdc', u'hdc'), 'bootOrder': ('', None), 'boot': ([], None), 'readonly': (True, True), 'address': ({u'bus': u'1', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'0'}, {u'bus': u'1', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'0'}), 'path': ('', ''), 'type': (u'cdrom', u'cdrom')}
>Thread-76::DEBUG::2016-03-18 17:26:11,623::vm::4399::virt.vm::(_getUnderlyingDriveInfo) vmId=`ca440cf8-b140-46c1-8658-c2c71d0229cf`::Matched {'name': (u'hdc', None), 'bootOrder': ('', None), 'boot': ([], None), 'readonly': (True, None), 'address': ({u'bus': u'1', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'0'}, None), 'path': ('', None), 'type': (u'cdrom', None)}
>Thread-76::DEBUG::2016-03-18 17:26:11,624::vm::4358::virt.vm::(_getUnderlyingDriveInfo) vmId=`ca440cf8-b140-46c1-8658-c2c71d0229cf`::Looking for drive with attributes {'name': u'vda', 'bootOrder': u'2', 'boot': [<DOM Element: boot at 0x7fac68062c68>], 'readonly': False, 'address': {u'slot': u'0x06', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, 'path': u'/rhev/data-center/acc8b348-81f6-4bf2-9ffe-f1da755bb38d/c1d2e073-fa2e-47a9-8a0c-3ceefad91685/images/e7e0392e-bcb9-4486-9e41-e163296528f5/81610d39-bca1-4c94-b193-fae83a8a1912', 'type': u'disk'}
>Thread-76::DEBUG::2016-03-18 17:26:11,624::vm::4379::virt.vm::(_getUnderlyingDriveInfo) vmId=`ca440cf8-b140-46c1-8658-c2c71d0229cf`::Matched {'name': (u'vda', u'vda'), 'bootOrder': (u'2', u'2'), 'boot': ([<DOM Element: boot at 0x7fac68062c68>], None), 'readonly': (False, False), 'address': ({u'slot': u'0x06', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, {u'slot': u'0x06', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}), 'path': (u'/rhev/data-center/acc8b348-81f6-4bf2-9ffe-f1da755bb38d/c1d2e073-fa2e-47a9-8a0c-3ceefad91685/images/e7e0392e-bcb9-4486-9e41-e163296528f5/81610d39-bca1-4c94-b193-fae83a8a1912', u'/rhev/data-center/acc8b348-81f6-4bf2-9ffe-f1da755bb38d/c1d2e073-fa2e-47a9-8a0c-3ceefad91685/images/e7e0392e-bcb9-4486-9e41-e163296528f5/81610d39-bca1-4c94-b193-fae83a8a1912'), 'type': (u'disk', u'disk')}
>Thread-76::DEBUG::2016-03-18 17:26:11,625::vm::4399::virt.vm::(_getUnderlyingDriveInfo) vmId=`ca440cf8-b140-46c1-8658-c2c71d0229cf`::Matched {'name': (u'vda', None), 'bootOrder': (u'2', None), 'boot': ([<DOM Element: boot at 0x7fac68062c68>], None), 'readonly': (False, None), 'address': ({u'slot': u'0x06', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, None), 'path': (u'/rhev/data-center/acc8b348-81f6-4bf2-9ffe-f1da755bb38d/c1d2e073-fa2e-47a9-8a0c-3ceefad91685/images/e7e0392e-bcb9-4486-9e41-e163296528f5/81610d39-bca1-4c94-b193-fae83a8a1912', None), 'type': (u'disk', None)}
>Thread-76::DEBUG::2016-03-18 17:26:11,639::vmchannels::218::vds::(register) Add fileno 35 to listener's channels.
>Thread-76::INFO::2016-03-18 17:26:11,642::vm::5084::virt.vm::(_logGuestCpuStatus) vmId=`ca440cf8-b140-46c1-8658-c2c71d0229cf`::CPU running: domain initialization
>Thread-76::DEBUG::2016-03-18 17:26:11,722::__init__::206::jsonrpc.Notification::(emit) Sending event {"params": {"notify_time": 4388292390, "ca440cf8-b140-46c1-8658-c2c71d0229cf": {"status": "Powering up", "displayInfo": [{"tlsPort": "5901", "ipAddress": "10.66.83.177", "type": "spice", "port": "5900"}], "hash": "-2532556405394263326", "displayIp": "10.66.83.177", "displayPort": "5900", "displaySecurePort": "5901", "timeOffset": "0", "pauseCode": "NOERR", "vcpuQuota": "-1", "cpuUser": "0.00", "monitorResponse": "0", "elapsedTime": "1", "displayType": "qxl", "cpuSys": "0.00", "clientIp": "", "vcpuPeriod": 100000}}, "jsonrpc": "2.0", "method": "|virt|VM_status|ca440cf8-b140-46c1-8658-c2c71d0229cf"}
>mailbox.SPMMonitor::DEBUG::2016-03-18 17:26:11,753::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) /usr/bin/taskset --cpu-list 0-1 dd if=/rhev/data-center/acc8b348-81f6-4bf2-9ffe-f1da755bb38d/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000 (cwd None)
>mailbox.SPMMonitor::DEBUG::2016-03-18 17:26:11,787::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0143049 s, 71.6 MB/s\n'; <rc> = 0
>VM Channels Listener::DEBUG::2016-03-18 17:26:12,573::vmchannels::125::vds::(_do_add_channels) fileno 35 was added to unconnected channels.
>VM Channels Listener::DEBUG::2016-03-18 17:26:12,573::guestagent::225::virt.vm::(_connect) vmId=`ca440cf8-b140-46c1-8658-c2c71d0229cf`::Attempting connection to /var/lib/libvirt/qemu/channels/ca440cf8-b140-46c1-8658-c2c71d0229cf.com.redhat.rhevm.vdsm
>VM Channels Listener::DEBUG::2016-03-18 17:26:12,574::guestagent::228::virt.vm::(_connect) vmId=`ca440cf8-b140-46c1-8658-c2c71d0229cf`::Connected to /var/lib/libvirt/qemu/channels/ca440cf8-b140-46c1-8658-c2c71d0229cf.com.redhat.rhevm.vdsm
>VM Channels Listener::DEBUG::2016-03-18 17:26:12,574::vmchannels::166::vds::(_handle_unconnected) Connecting to fileno 35 succeeded.
>jsonrpc.Executor/2::DEBUG::2016-03-18 17:26:12,730::__init__::503::jsonrpc.JsonRpcServer::(_serveRequest) Calling 'Host.getVMFullList' in bridge with {u'vmList': [u'ca440cf8-b140-46c1-8658-c2c71d0229cf']}
>jsonrpc.Executor/2::DEBUG::2016-03-18 17:26:12,740::__init__::533::jsonrpc.JsonRpcServer::(_serveRequest) Return 'Host.getVMFullList' in bridge with [{u'acpiEnable': u'true', u'emulatedMachine': u'pc-i440fx-rhel7.2.0', 'pid': '20355', u'memGuaranteedSize': 1024, u'transparentHugePages': u'true', 'displayPort': u'5900', 'displaySecurePort': u'5901', u'spiceSslCipherSuite': u'DEFAULT', u'cpuType': u'Opteron_G1', u'smp': u'1', 'pauseCode': 'NOERR', u'guestNumaNodes': [{u'nodeIndex': 0, u'cpus': u'0', u'memory': u'1024'}], u'smartcardEnable': u'false', u'custom': {}, u'vmType': u'kvm', u'memSize': 1024, u'smpCoresPerSocket': u'1', u'vmName': u'vm1', u'nice': u'0', 'status': 'Up', u'maxMemSize': 4194304, u'bootMenuEnable': u'false', u'vmId': u'ca440cf8-b140-46c1-8658-c2c71d0229cf', u'copyPasteEnable': u'true', 'displayIp': '10.66.83.177', u'smpThreadsPerCore': u'1', 'guestDiskMapping': {}, u'spiceSecureChannels': u'smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard', u'fileTransferEnable': u'true', 'nicModel': 'rtl8139,pv', u'keyboardLayout': u'en-us', u'kvmEnable': u'true', u'displayNetwork': u'ovirtmgmt', u'devices': [{'target': 1048576, u'specParams': {u'model': u'virtio'}, 'alias': u'balloon0', 'deviceType': u'balloon', u'deviceId': u'cacda659-c0fd-4a88-9eac-e9fbfc4f9e94', 'address': {u'slot': u'0x07', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, u'device': u'memballoon', u'type': u'balloon'}, {u'index': u'0', 'alias': u'scsi0', u'specParams': {}, 'deviceType': u'controller', u'deviceId': u'390b4cc9-f824-4be8-b3ba-04f05045e90d', 'address': {u'slot': u'0x04', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, u'device': u'scsi', u'model': u'virtio-scsi', u'type': u'controller'}, {u'specParams': {}, 'alias': u'virtio-serial0', 'deviceType': u'controller', u'deviceId': u'1a747327-a65f-4b7b-9530-e60a90e6c715', 'address': {u'slot': u'0x05', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, u'device': u'virtio-serial', u'type': u'controller'}, {u'specParams': {u'vram': u'8192', u'ram': u'65536', u'heads': u'1', u'vgamem': u'16384'}, 'alias': u'video0', 'deviceType': u'video', u'deviceId': u'1245228b-332e-4678-890b-78010aa775e2', 'address': {u'slot': u'0x02', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, u'device': u'qxl', u'type': u'video'}, {'tlsPort': u'5901', u'specParams': {u'fileTransferEnable': u'true', u'copyPasteEnable': u'true', 'displayIp': '10.66.83.177', 'displayNetwork': u'ovirtmgmt'}, 'deviceType': u'graphics', u'deviceId': u'5e38528d-f474-4a71-a1f2-ee58a2b1376d', u'device': u'spice', u'type': u'graphics', 'port': u'5900'}, {u'nicModel': u'pv', u'macAddr': u'00:1a:4a:16:01:51', u'linkActive': True, u'network': u'ovirtmgmt', u'specParams': {u'inbound': {}, u'outbound': {}}, u'bootOrder': u'1', u'filter': u'vdsm-no-mac-spoofing', 'alias': u'net0', 'deviceType': u'interface', u'deviceId': u'2d1be0ea-ec38-4f63-a42c-e4bee0d02d2e', 'address': {u'slot': u'0x03', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, u'device': u'bridge', u'type': u'interface', 'name': u'vnet0'}, {u'index': u'2', u'iface': u'ide', 'name': u'hdc', 'alias': u'ide0-1-0', u'specParams': {u'path': u''}, u'readonly': 'True', 'deviceType': u'disk', u'deviceId': u'4ff576a1-93f2-451e-a220-151a30c2c636', 'address': {u'bus': u'1', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'0'}, u'device': u'cdrom', u'shared': u'false', u'path': '', u'type': u'disk'}, {'address': {u'slot': u'0x06', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, 'volumeInfo': {'domainID': u'c1d2e073-fa2e-47a9-8a0c-3ceefad91685', 'volType': 'path', 'leaseOffset': 0, 'volumeID': u'81610d39-bca1-4c94-b193-fae83a8a1912', 'leasePath': u'/rhev/data-center/mnt/10.73.194.27:_vol_S3_libvirtauto_yy_nfs1/c1d2e073-fa2e-47a9-8a0c-3ceefad91685/images/e7e0392e-bcb9-4486-9e41-e163296528f5/81610d39-bca1-4c94-b193-fae83a8a1912.lease', 'imageID': u'e7e0392e-bcb9-4486-9e41-e163296528f5', 'path': u'/rhev/data-center/mnt/10.73.194.27:_vol_S3_libvirtauto_yy_nfs1/c1d2e073-fa2e-47a9-8a0c-3ceefad91685/images/e7e0392e-bcb9-4486-9e41-e163296528f5/81610d39-bca1-4c94-b193-fae83a8a1912'}, u'index': 0, u'iface': u'virtio', 'apparentsize': '5368709120', u'specParams': {}, u'imageID': u'e7e0392e-bcb9-4486-9e41-e163296528f5', u'readonly': 'False', 'deviceType': u'disk', u'shared': u'false', 'truesize': '0', u'type': u'disk', u'domainID': u'c1d2e073-fa2e-47a9-8a0c-3ceefad91685', 'reqsize': '0', u'format': u'raw', u'deviceId': u'e7e0392e-bcb9-4486-9e41-e163296528f5', u'poolID': u'acc8b348-81f6-4bf2-9ffe-f1da755bb38d', u'device': u'disk', 'path': u'/rhev/data-center/acc8b348-81f6-4bf2-9ffe-f1da755bb38d/c1d2e073-fa2e-47a9-8a0c-3ceefad91685/images/e7e0392e-bcb9-4486-9e41-e163296528f5/81610d39-bca1-4c94-b193-fae83a8a1912', u'propagateErrors': u'off', u'optional': u'false', 'name': u'vda', u'bootOrder': u'2', u'volumeID': u'81610d39-bca1-4c94-b193-fae83a8a1912', 'alias': u'virtio-disk0', 'volumeChain': [{'domainID': u'c1d2e073-fa2e-47a9-8a0c-3ceefad91685', 'volType': 'path', 'leaseOffset': 0, 'volumeID': u'81610d39-bca1-4c94-b193-fae83a8a1912', 'leasePath': u'/rhev/data-center/mnt/10.73.194.27:_vol_S3_libvirtauto_yy_nfs1/c1d2e073-fa2e-47a9-8a0c-3ceefad91685/images/e7e0392e-bcb9-4486-9e41-e163296528f5/81610d39-bca1-4c94-b193-fae83a8a1912.lease', 'imageID': u'e7e0392e-bcb9-4486-9e41-e163296528f5', 'path': u'/rhev/data-center/mnt/10.73.194.27:_vol_S3_libvirtauto_yy_nfs1/c1d2e073-fa2e-47a9-8a0c-3ceefad91685/images/e7e0392e-bcb9-4486-9e41-e163296528f5/81610d39-bca1-4c94-b193-fae83a8a1912'}]}, {'device': u'usb', 'alias': u'usb', 'deviceType': 'controller', 'type': 'controller', 'address': {u'slot': u'0x01', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x2'}}, {'device': u'ide', 'alias': u'ide', 'deviceType': 'controller', 'type': 'controller', 'address': {u'slot': u'0x01', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x1'}}, {'device': u'unix', 'alias': u'channel0', 'deviceType': u'channel', 'type': u'channel', 'address': {u'bus': u'0', u'controller': u'0', u'type': u'virtio-serial', u'port': u'1'}}, {'device': u'unix', 'alias': u'channel1', 'deviceType': u'channel', 'type': u'channel', 'address': {u'bus': u'0', u'controller': u'0', u'type': u'virtio-serial', u'port': u'2'}}, {'device': u'spicevmc', 'alias': u'channel2', 'deviceType': u'channel', 'type': u'channel', 'address': {u'bus': u'0', u'controller': u'0', u'type': u'virtio-serial', u'port': u'3'}}], u'display': 'qxl', u'timeOffset': u'0', u'maxVCpus': u'16', 'clientIp': '', 'statusTime': '4388293410', u'maxMemSlots': 16}]
>mailbox.SPMMonitor::DEBUG::2016-03-18 17:26:13,807::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) /usr/bin/taskset --cpu-list 0-1 dd if=/rhev/data-center/acc8b348-81f6-4bf2-9ffe-f1da755bb38d/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000 (cwd None)
>mailbox.SPMMonitor::DEBUG::2016-03-18 17:26:13,839::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0136631 s, 74.9 MB/s\n'; <rc> = 0
>jsonrpc.Executor/4::DEBUG::2016-03-18 17:26:14,792::task::595::Storage.TaskManager.Task::(_updateState) Task=`6802ada8-cc7a-4500-95f4-3e4edbdf78f9`::moving from state init -> state preparing
>jsonrpc.Executor/4::INFO::2016-03-18 17:26:14,793::logUtils::48::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>jsonrpc.Executor/4::INFO::2016-03-18 17:26:14,793::logUtils::51::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'c1d2e073-fa2e-47a9-8a0c-3ceefad91685': {'code': 0, 'actual': True, 'version': 3, 'acquired': True, 'delay': '0.00101759', 'lastCheck': '4.4', 'valid': True}}
>jsonrpc.Executor/4::DEBUG::2016-03-18 17:26:14,793::task::1191::Storage.TaskManager.Task::(prepare) Task=`6802ada8-cc7a-4500-95f4-3e4edbdf78f9`::finished: {u'c1d2e073-fa2e-47a9-8a0c-3ceefad91685': {'code': 0, 'actual': True, 'version': 3, 'acquired': True, 'delay': '0.00101759', 'lastCheck': '4.4', 'valid': True}}
>jsonrpc.Executor/4::DEBUG::2016-03-18 17:26:14,793::task::595::Storage.TaskManager.Task::(_updateState) Task=`6802ada8-cc7a-4500-95f4-3e4edbdf78f9`::moving from state preparing -> state finished
>jsonrpc.Executor/4::DEBUG::2016-03-18 17:26:14,794::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>jsonrpc.Executor/4::DEBUG::2016-03-18 17:26:14,794::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>jsonrpc.Executor/4::DEBUG::2016-03-18 17:26:14,794::task::993::Storage.TaskManager.Task::(_decref) Task=`6802ada8-cc7a-4500-95f4-3e4edbdf78f9`::ref 0 aborting False
>mailbox.SPMMonitor::DEBUG::2016-03-18 17:26:15,857::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) /usr/bin/taskset --cpu-list 0-1 dd if=/rhev/data-center/acc8b348-81f6-4bf2-9ffe-f1da755bb38d/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000 (cwd None)
>mailbox.SPMMonitor::DEBUG::2016-03-18 17:26:15,889::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0131903 s, 77.6 MB/s\n'; <rc> = 0
>periodic/0::WARNING::2016-03-18 17:26:16,186::periodic::258::virt.periodic.VmDispatcher::(__call__) could not run <class 'virt.periodic.BlockjobMonitor'> on [u'ca440cf8-b140-46c1-8658-c2c71d0229cf']
>MainThread::INFO::2016-03-18 17:26:31,105::vdsm::162::vds::(run) (PID: 20483) I am the actual vdsm 4.17.23.1-0.el7ev amd-4450b-4-1.englab.nay.redhat.com (3.10.0-363.el7.x86_64)
>MainThread::INFO::2016-03-18 17:26:31,106::vdsm::285::vds::(__set_cpu_affinity) VDSM will run with cpu affinity: frozenset([1])
>MainThread::DEBUG::2016-03-18 17:26:31,106::utils::671::root::(execCmd) /usr/bin/taskset --all-tasks --pid --cpu-list 1 20483 (cwd None)
>MainThread::DEBUG::2016-03-18 17:26:31,125::utils::689::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
>MainThread::DEBUG::2016-03-18 17:26:31,127::resourceManager::424::Storage.ResourceManager::(registerNamespace) Registering namespace 'Storage'
>MainThread::DEBUG::2016-03-18 17:26:31,127::threadPool::29::Storage.ThreadPool::(__init__) Enter - numThreads: 10, waitTimeout: 3, maxTasks: 500
>MainThread::DEBUG::2016-03-18 17:26:31,132::fileUtils::143::Storage.fileUtils::(createdir) Creating directory: /rhev/data-center/mnt mode: None
>MainThread::WARNING::2016-03-18 17:26:31,133::fileUtils::152::Storage.fileUtils::(createdir) Dir /rhev/data-center/mnt already exists
>MainThread::DEBUG::2016-03-18 17:26:31,155::sp::395::Storage.StoragePool::(cleanupMasterMount) master `/rhev/data-center/mnt/blockSD/c92de3f8-b279-489f-b69f-1b2e7bfdfccd/master` is not mounted, skipping
>MainThread::DEBUG::2016-03-18 17:26:31,250::hsm::409::Storage.Misc.excCmd::(__validateLvmLockingType) /usr/bin/taskset --cpu-list 0-1 /usr/bin/sudo -n /usr/sbin/lvm dumpconfig global/locking_type (cwd None)
>MainThread::DEBUG::2016-03-18 17:26:31,295::hsm::409::Storage.Misc.excCmd::(__validateLvmLockingType) SUCCESS: <err> = ''; <rc> = 0
>MainThread::DEBUG::2016-03-18 17:26:31,296::hsm::433::Storage.HSM::(__cleanStorageRepository) Started cleaning storage repository at '/rhev/data-center'
>MainThread::DEBUG::2016-03-18 17:26:31,299::hsm::465::Storage.HSM::(__cleanStorageRepository) White list: ['/rhev/data-center/hsm-tasks', '/rhev/data-center/hsm-tasks/*', '/rhev/data-center/mnt']
>MainThread::DEBUG::2016-03-18 17:26:31,300::hsm::466::Storage.HSM::(__cleanStorageRepository) Mount list: ['/rhev/data-center/mnt/10.73.194.27:_vol_S3_libvirtauto_yy_nfs1']
>MainThread::DEBUG::2016-03-18 17:26:31,300::hsm::468::Storage.HSM::(__cleanStorageRepository) Cleaning leftovers
>MainThread::DEBUG::2016-03-18 17:26:31,302::hsm::511::Storage.HSM::(__cleanStorageRepository) Finished cleaning storage repository at '/rhev/data-center'
>MainThread::INFO::2016-03-18 17:26:31,305::dispatcher::46::Storage.Dispatcher::(__init__) Starting StorageDispatcher...
>MainThread::DEBUG::2016-03-18 17:26:31,306::schedule::98::Scheduler::(start) Starting scheduler vdsm.Scheduler
>storageRefresh::DEBUG::2016-03-18 17:26:31,306::misc::750::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>storageRefresh::DEBUG::2016-03-18 17:26:31,306::misc::753::Storage.SamplingMethod::(__call__) Got in to sampling method
>storageRefresh::DEBUG::2016-03-18 17:26:31,307::misc::750::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>storageRefresh::DEBUG::2016-03-18 17:26:31,307::misc::753::Storage.SamplingMethod::(__call__) Got in to sampling method
>storageRefresh::DEBUG::2016-03-18 17:26:31,307::iscsi::434::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
>storageRefresh::DEBUG::2016-03-18 17:26:31,307::iscsiadm::97::Storage.Misc.excCmd::(_runCmd) /usr/bin/taskset --cpu-list 0-1 /usr/bin/sudo -n /sbin/iscsiadm -m session -R (cwd None)
>vdsm.Scheduler::DEBUG::2016-03-18 17:26:31,396::schedule::142::Scheduler::(_run) started
>MainThread::DEBUG::2016-03-18 17:26:31,421::task::595::Storage.TaskManager.Task::(_updateState) Task=`4f30cfe7-ac11-4f58-bf50-4eaa2dfc9bdf`::moving from state init -> state preparing
>MainThread::INFO::2016-03-18 17:26:31,421::logUtils::48::dispatcher::(wrapper) Run and protect: registerDomainStateChangeCallback(callbackFunc=<functools.partial object at 0x3640050>)
>MainThread::INFO::2016-03-18 17:26:31,422::logUtils::51::dispatcher::(wrapper) Run and protect: registerDomainStateChangeCallback, Return response: None
>MainThread::DEBUG::2016-03-18 17:26:31,422::task::1191::Storage.TaskManager.Task::(prepare) Task=`4f30cfe7-ac11-4f58-bf50-4eaa2dfc9bdf`::finished: None
>MainThread::DEBUG::2016-03-18 17:26:31,422::task::595::Storage.TaskManager.Task::(_updateState) Task=`4f30cfe7-ac11-4f58-bf50-4eaa2dfc9bdf`::moving from state preparing -> state finished
>MainThread::DEBUG::2016-03-18 17:26:31,422::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>MainThread::DEBUG::2016-03-18 17:26:31,422::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>MainThread::DEBUG::2016-03-18 17:26:31,423::task::993::Storage.TaskManager.Task::(_decref) Task=`4f30cfe7-ac11-4f58-bf50-4eaa2dfc9bdf`::ref 0 aborting False
>MainThread::INFO::2016-03-18 17:26:31,423::momIF::46::MOM::(__init__) Preparing MOM interface
>MainThread::INFO::2016-03-18 17:26:31,425::momIF::55::MOM::(__init__) Using named unix socket /var/run/vdsm/mom-vdsm.sock
>MainThread::INFO::2016-03-18 17:26:31,427::secret::90::root::(clear) Unregistering all secrests
>MainThread::DEBUG::2016-03-18 17:26:31,427::libvirtconnection::161::root::(get) trying to connect libvirt
>MainThread::INFO::2016-03-18 17:26:31,455::vmchannels::211::vds::(settimeout) Setting channels' timeout to 30 seconds.
>clientIFinit::DEBUG::2016-03-18 17:26:31,457::clientIF::462::vds::(_recoverExistingVms) recovery: started
>MainThread::INFO::2016-03-18 17:26:31,459::protocoldetector::172::vds.MultiProtocolAcceptor::(__init__) Listening at 0.0.0.0:54321
>MainThread::DEBUG::2016-03-18 17:26:31,467::protocoldetector::199::vds.MultiProtocolAcceptor::(add_detector) Adding detector <rpc.bindingxmlrpc.XmlDetector instance at 0x36f3998>
>storageRefresh::DEBUG::2016-03-18 17:26:31,508::misc::760::Storage.SamplingMethod::(__call__) Returning last result
>storageRefresh::DEBUG::2016-03-18 17:26:31,508::misc::750::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.hba.rescan)
>storageRefresh::DEBUG::2016-03-18 17:26:31,508::misc::753::Storage.SamplingMethod::(__call__) Got in to sampling method
>storageRefresh::DEBUG::2016-03-18 17:26:31,508::hba::56::Storage.HBA::(rescan) Starting scan
>storageRefresh::DEBUG::2016-03-18 17:26:31,509::supervdsm::76::SuperVdsmProxy::(_connect) Trying to connect to Super Vdsm
>VM Channels Listener::DEBUG::2016-03-18 17:26:31,584::vmchannels::193::vds::(run) Starting VM channels listener thread.
>MainThread::DEBUG::2016-03-18 17:26:31,585::protocoldetector::199::vds.MultiProtocolAcceptor::(add_detector) Adding detector <yajsonrpc.stompreactor.StompDetector instance at 0x38971b8>
>MainThread::DEBUG::2016-03-18 17:26:31,585::executor::69::Executor::(start) Starting executor
>MainThread::DEBUG::2016-03-18 17:26:31,585::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/0
>MainThread::DEBUG::2016-03-18 17:26:31,587::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/1
>jsonrpc.Executor/0::DEBUG::2016-03-18 17:26:31,588::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:26:31,592::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/2
>jsonrpc.Executor/1::DEBUG::2016-03-18 17:26:31,593::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:26:31,593::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/3
>jsonrpc.Executor/2::DEBUG::2016-03-18 17:26:31,593::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:26:31,598::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/4
>jsonrpc.Executor/3::DEBUG::2016-03-18 17:26:31,599::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:26:31,605::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/5
>jsonrpc.Executor/4::DEBUG::2016-03-18 17:26:31,607::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:26:31,607::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/6
>jsonrpc.Executor/5::DEBUG::2016-03-18 17:26:31,608::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:26:31,608::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/7
>jsonrpc.Executor/6::DEBUG::2016-03-18 17:26:31,608::executor::171::Executor::(_run) Worker started
>jsonrpc.Executor/7::DEBUG::2016-03-18 17:26:31,609::executor::171::Executor::(_run) Worker started
>BindingXMLRPC::INFO::2016-03-18 17:26:31,610::bindingxmlrpc::62::vds::(threaded_start) XMLRPC server running
>MainThread::DEBUG::2016-03-18 17:26:31,617::executor::69::Executor::(start) Starting executor
>MainThread::DEBUG::2016-03-18 17:26:31,618::executor::157::Executor::(__init__) Starting worker periodic/0
>MainThread::DEBUG::2016-03-18 17:26:31,620::executor::157::Executor::(__init__) Starting worker periodic/1
>periodic/0::DEBUG::2016-03-18 17:26:31,620::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:26:31,621::executor::157::Executor::(__init__) Starting worker periodic/2
>periodic/1::DEBUG::2016-03-18 17:26:31,621::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:26:31,621::executor::157::Executor::(__init__) Starting worker periodic/3
>periodic/2::DEBUG::2016-03-18 17:26:31,622::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:26:31,622::libvirtconnection::161::root::(get) trying to connect libvirt
>periodic/3::DEBUG::2016-03-18 17:26:31,623::executor::171::Executor::(_run) Worker started
>clientIFinit::DEBUG::2016-03-18 17:26:31,657::clientIF::575::vds::(_recoverVm) Trying to recover ca440cf8-b140-46c1-8658-c2c71d0229cf
>MainThread::DEBUG::2016-03-18 17:26:31,710::periodic::153::virt.periodic.Operation::(start) starting operation <VmDispatcher operation=<class 'virt.periodic.UpdateVolumes'> at 0x38be390>
>MainThread::DEBUG::2016-03-18 17:26:31,711::periodic::153::virt.periodic.Operation::(start) starting operation <VmDispatcher operation=<class 'virt.periodic.NumaInfoMonitor'> at 0x38be5d0>
>MainThread::DEBUG::2016-03-18 17:26:31,711::periodic::153::virt.periodic.Operation::(start) starting operation <VmDispatcher operation=<class 'virt.periodic.BlockjobMonitor'> at 0x38be650>
>MainThread::DEBUG::2016-03-18 17:26:31,711::periodic::153::virt.periodic.Operation::(start) starting operation <VMBulkSampler at 0x38be6d0>
>MainThread::DEBUG::2016-03-18 17:26:31,711::periodic::153::virt.periodic.Operation::(start) starting operation <VmDispatcher operation=<class 'virt.periodic.DriveWatermarkMonitor'> at 0x391fd50>
>periodic/1::WARNING::2016-03-18 17:26:31,726::periodic::285::virt.vm::(__call__) vmId=`ca440cf8-b140-46c1-8658-c2c71d0229cf`::could not run on ca440cf8-b140-46c1-8658-c2c71d0229cf: domain not connected
>periodic/2::WARNING::2016-03-18 17:26:31,727::periodic::258::virt.periodic.VmDispatcher::(__call__) could not run <class 'virt.periodic.BlockjobMonitor'> on [u'ca440cf8-b140-46c1-8658-c2c71d0229cf']
>clientIFinit::INFO::2016-03-18 17:26:31,728::clientIF::479::vds::(_recoverExistingVms) recovery [1:1/1]: recovered domain ca440cf8-b140-46c1-8658-c2c71d0229cf from libvirt
>clientIFinit::INFO::2016-03-18 17:26:31,728::clientIF::521::vds::(_recoverExistingVms) recovery: waiting for 1 domains to go up
>Thread-13::DEBUG::2016-03-18 17:26:31,728::vm::697::virt.vm::(_startUnderlyingVm) vmId=`ca440cf8-b140-46c1-8658-c2c71d0229cf`::Start
>Thread-13::INFO::2016-03-18 17:26:31,729::vm::1850::virt.vm::(_run) vmId=`ca440cf8-b140-46c1-8658-c2c71d0229cf`::VM wrapper has started
>Thread-13::DEBUG::2016-03-18 17:26:31,730::task::595::Storage.TaskManager.Task::(_updateState) Task=`23c44299-0c95-4a15-bbe1-9c18a5dd9a35`::moving from state init -> state preparing
>Thread-13::INFO::2016-03-18 17:26:31,730::logUtils::48::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID=u'c1d2e073-fa2e-47a9-8a0c-3ceefad91685', spUUID=u'acc8b348-81f6-4bf2-9ffe-f1da755bb38d', imgUUID=u'e7e0392e-bcb9-4486-9e41-e163296528f5', volUUID=u'81610d39-bca1-4c94-b193-fae83a8a1912', options=None)
>Thread-13::DEBUG::2016-03-18 17:26:31,730::misc::750::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>MainThread::INFO::2016-03-18 17:26:46,688::vdsm::162::vds::(run) (PID: 20653) I am the actual vdsm 4.17.23.1-0.el7ev amd-4450b-4-1.englab.nay.redhat.com (3.10.0-363.el7.x86_64)
>MainThread::INFO::2016-03-18 17:26:46,689::vdsm::285::vds::(__set_cpu_affinity) VDSM will run with cpu affinity: frozenset([1])
>MainThread::DEBUG::2016-03-18 17:26:46,690::utils::671::root::(execCmd) /usr/bin/taskset --all-tasks --pid --cpu-list 1 20653 (cwd None)
>MainThread::DEBUG::2016-03-18 17:26:46,697::utils::689::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
>MainThread::DEBUG::2016-03-18 17:26:46,698::resourceManager::424::Storage.ResourceManager::(registerNamespace) Registering namespace 'Storage'
>MainThread::DEBUG::2016-03-18 17:26:46,699::threadPool::29::Storage.ThreadPool::(__init__) Enter - numThreads: 10, waitTimeout: 3, maxTasks: 500
>MainThread::DEBUG::2016-03-18 17:26:46,704::fileUtils::143::Storage.fileUtils::(createdir) Creating directory: /rhev/data-center/mnt mode: None
>MainThread::WARNING::2016-03-18 17:26:46,704::fileUtils::152::Storage.fileUtils::(createdir) Dir /rhev/data-center/mnt already exists
>MainThread::DEBUG::2016-03-18 17:26:46,715::sp::395::Storage.StoragePool::(cleanupMasterMount) master `/rhev/data-center/mnt/blockSD/c92de3f8-b279-489f-b69f-1b2e7bfdfccd/master` is not mounted, skipping
>MainThread::DEBUG::2016-03-18 17:26:46,786::hsm::409::Storage.Misc.excCmd::(__validateLvmLockingType) /usr/bin/taskset --cpu-list 0-1 /usr/bin/sudo -n /usr/sbin/lvm dumpconfig global/locking_type (cwd None)
>MainThread::DEBUG::2016-03-18 17:26:46,884::hsm::409::Storage.Misc.excCmd::(__validateLvmLockingType) SUCCESS: <err> = ''; <rc> = 0
>MainThread::DEBUG::2016-03-18 17:26:46,884::hsm::433::Storage.HSM::(__cleanStorageRepository) Started cleaning storage repository at '/rhev/data-center'
>MainThread::DEBUG::2016-03-18 17:26:46,887::hsm::465::Storage.HSM::(__cleanStorageRepository) White list: ['/rhev/data-center/hsm-tasks', '/rhev/data-center/hsm-tasks/*', '/rhev/data-center/mnt']
>MainThread::DEBUG::2016-03-18 17:26:46,888::hsm::466::Storage.HSM::(__cleanStorageRepository) Mount list: ['/rhev/data-center/mnt/10.73.194.27:_vol_S3_libvirtauto_yy_nfs1']
>MainThread::DEBUG::2016-03-18 17:26:46,888::hsm::468::Storage.HSM::(__cleanStorageRepository) Cleaning leftovers
>MainThread::DEBUG::2016-03-18 17:26:46,890::hsm::511::Storage.HSM::(__cleanStorageRepository) Finished cleaning storage repository at '/rhev/data-center'
>MainThread::INFO::2016-03-18 17:26:46,893::dispatcher::46::Storage.Dispatcher::(__init__) Starting StorageDispatcher...
>MainThread::DEBUG::2016-03-18 17:26:46,893::schedule::98::Scheduler::(start) Starting scheduler vdsm.Scheduler
>storageRefresh::DEBUG::2016-03-18 17:26:46,895::misc::750::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>storageRefresh::DEBUG::2016-03-18 17:26:46,895::misc::753::Storage.SamplingMethod::(__call__) Got in to sampling method
>storageRefresh::DEBUG::2016-03-18 17:26:46,895::misc::750::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>storageRefresh::DEBUG::2016-03-18 17:26:46,895::misc::753::Storage.SamplingMethod::(__call__) Got in to sampling method
>storageRefresh::DEBUG::2016-03-18 17:26:46,895::iscsi::434::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
>storageRefresh::DEBUG::2016-03-18 17:26:46,896::iscsiadm::97::Storage.Misc.excCmd::(_runCmd) /usr/bin/taskset --cpu-list 0-1 /usr/bin/sudo -n /sbin/iscsiadm -m session -R (cwd None)
>MainThread::DEBUG::2016-03-18 17:26:47,009::task::595::Storage.TaskManager.Task::(_updateState) Task=`e7ba179c-5a94-4d3c-868a-38a0299cf45f`::moving from state init -> state preparing
>MainThread::INFO::2016-03-18 17:26:47,010::logUtils::48::dispatcher::(wrapper) Run and protect: registerDomainStateChangeCallback(callbackFunc=<functools.partial object at 0x264d050>)
>MainThread::INFO::2016-03-18 17:26:47,010::logUtils::51::dispatcher::(wrapper) Run and protect: registerDomainStateChangeCallback, Return response: None
>MainThread::DEBUG::2016-03-18 17:26:47,010::task::1191::Storage.TaskManager.Task::(prepare) Task=`e7ba179c-5a94-4d3c-868a-38a0299cf45f`::finished: None
>MainThread::DEBUG::2016-03-18 17:26:47,010::task::595::Storage.TaskManager.Task::(_updateState) Task=`e7ba179c-5a94-4d3c-868a-38a0299cf45f`::moving from state preparing -> state finished
>MainThread::DEBUG::2016-03-18 17:26:47,011::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>MainThread::DEBUG::2016-03-18 17:26:47,011::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>MainThread::DEBUG::2016-03-18 17:26:47,011::task::993::Storage.TaskManager.Task::(_decref) Task=`e7ba179c-5a94-4d3c-868a-38a0299cf45f`::ref 0 aborting False
>vdsm.Scheduler::DEBUG::2016-03-18 17:26:47,012::schedule::142::Scheduler::(_run) started
>MainThread::INFO::2016-03-18 17:26:47,013::momIF::46::MOM::(__init__) Preparing MOM interface
>MainThread::INFO::2016-03-18 17:26:47,015::momIF::55::MOM::(__init__) Using named unix socket /var/run/vdsm/mom-vdsm.sock
>MainThread::INFO::2016-03-18 17:26:47,016::secret::90::root::(clear) Unregistering all secrests
>MainThread::DEBUG::2016-03-18 17:26:47,017::libvirtconnection::161::root::(get) trying to connect libvirt
>storageRefresh::DEBUG::2016-03-18 17:26:47,041::misc::760::Storage.SamplingMethod::(__call__) Returning last result
>storageRefresh::DEBUG::2016-03-18 17:26:47,041::misc::750::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.hba.rescan)
>storageRefresh::DEBUG::2016-03-18 17:26:47,041::misc::753::Storage.SamplingMethod::(__call__) Got in to sampling method
>storageRefresh::DEBUG::2016-03-18 17:26:47,042::hba::56::Storage.HBA::(rescan) Starting scan
>storageRefresh::DEBUG::2016-03-18 17:26:47,042::supervdsm::76::SuperVdsmProxy::(_connect) Trying to connect to Super Vdsm
>MainThread::INFO::2016-03-18 17:26:47,065::vmchannels::211::vds::(settimeout) Setting channels' timeout to 30 seconds.
>clientIFinit::DEBUG::2016-03-18 17:26:47,065::clientIF::462::vds::(_recoverExistingVms) recovery: started
>MainThread::INFO::2016-03-18 17:26:47,068::protocoldetector::172::vds.MultiProtocolAcceptor::(__init__) Listening at 0.0.0.0:54321
>MainThread::DEBUG::2016-03-18 17:26:47,076::protocoldetector::199::vds.MultiProtocolAcceptor::(add_detector) Adding detector <rpc.bindingxmlrpc.XmlDetector instance at 0x2707a28>
>VM Channels Listener::DEBUG::2016-03-18 17:26:47,187::vmchannels::193::vds::(run) Starting VM channels listener thread.
>MainThread::DEBUG::2016-03-18 17:26:47,188::protocoldetector::199::vds.MultiProtocolAcceptor::(add_detector) Adding detector <yajsonrpc.stompreactor.StompDetector instance at 0x28a3c20>
>MainThread::DEBUG::2016-03-18 17:26:47,188::executor::69::Executor::(start) Starting executor
>MainThread::DEBUG::2016-03-18 17:26:47,189::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/0
>MainThread::DEBUG::2016-03-18 17:26:47,189::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/1
>jsonrpc.Executor/0::DEBUG::2016-03-18 17:26:47,191::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:26:47,193::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/2
>jsonrpc.Executor/1::DEBUG::2016-03-18 17:26:47,193::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:26:47,198::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/3
>jsonrpc.Executor/2::DEBUG::2016-03-18 17:26:47,198::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:26:47,200::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/4
>jsonrpc.Executor/3::DEBUG::2016-03-18 17:26:47,201::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:26:47,201::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/5
>jsonrpc.Executor/4::DEBUG::2016-03-18 17:26:47,202::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:26:47,202::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/6
>jsonrpc.Executor/5::DEBUG::2016-03-18 17:26:47,202::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:26:47,203::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/7
>jsonrpc.Executor/6::DEBUG::2016-03-18 17:26:47,203::executor::171::Executor::(_run) Worker started
>jsonrpc.Executor/7::DEBUG::2016-03-18 17:26:47,211::executor::171::Executor::(_run) Worker started
>BindingXMLRPC::INFO::2016-03-18 17:26:47,217::bindingxmlrpc::62::vds::(threaded_start) XMLRPC server running
>MainThread::DEBUG::2016-03-18 17:26:47,225::executor::69::Executor::(start) Starting executor
>MainThread::DEBUG::2016-03-18 17:26:47,226::executor::157::Executor::(__init__) Starting worker periodic/0
>MainThread::DEBUG::2016-03-18 17:26:47,226::executor::157::Executor::(__init__) Starting worker periodic/1
>periodic/0::DEBUG::2016-03-18 17:26:47,227::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:26:47,228::executor::157::Executor::(__init__) Starting worker periodic/2
>periodic/1::DEBUG::2016-03-18 17:26:47,229::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:26:47,229::executor::157::Executor::(__init__) Starting worker periodic/3
>periodic/2::DEBUG::2016-03-18 17:26:47,230::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:26:47,231::libvirtconnection::161::root::(get) trying to connect libvirt
>periodic/3::DEBUG::2016-03-18 17:26:47,232::executor::171::Executor::(_run) Worker started
>clientIFinit::DEBUG::2016-03-18 17:26:47,258::clientIF::575::vds::(_recoverVm) Trying to recover ca440cf8-b140-46c1-8658-c2c71d0229cf
>MainThread::DEBUG::2016-03-18 17:26:47,428::periodic::153::virt.periodic.Operation::(start) starting operation <VmDispatcher operation=<class 'virt.periodic.UpdateVolumes'> at 0x28c5450>
>MainThread::DEBUG::2016-03-18 17:26:47,428::periodic::153::virt.periodic.Operation::(start) starting operation <VmDispatcher operation=<class 'virt.periodic.NumaInfoMonitor'> at 0x28c5690>
>MainThread::DEBUG::2016-03-18 17:26:47,429::periodic::153::virt.periodic.Operation::(start) starting operation <VmDispatcher operation=<class 'virt.periodic.BlockjobMonitor'> at 0x28c5710>
>MainThread::DEBUG::2016-03-18 17:26:47,429::periodic::153::virt.periodic.Operation::(start) starting operation <VMBulkSampler at 0x28c5790>
>MainThread::DEBUG::2016-03-18 17:26:47,429::periodic::153::virt.periodic.Operation::(start) starting operation <VmDispatcher operation=<class 'virt.periodic.DriveWatermarkMonitor'> at 0x292ed50>
>periodic/1::WARNING::2016-03-18 17:26:47,443::periodic::285::virt.vm::(__call__) vmId=`ca440cf8-b140-46c1-8658-c2c71d0229cf`::could not run on ca440cf8-b140-46c1-8658-c2c71d0229cf: domain not connected
>periodic/2::WARNING::2016-03-18 17:26:47,445::periodic::258::virt.periodic.VmDispatcher::(__call__) could not run <class 'virt.periodic.BlockjobMonitor'> on [u'ca440cf8-b140-46c1-8658-c2c71d0229cf']
>clientIFinit::INFO::2016-03-18 17:26:47,447::clientIF::479::vds::(_recoverExistingVms) recovery [1:1/1]: recovered domain ca440cf8-b140-46c1-8658-c2c71d0229cf from libvirt
>clientIFinit::INFO::2016-03-18 17:26:47,448::clientIF::521::vds::(_recoverExistingVms) recovery: waiting for 1 domains to go up
>Thread-13::DEBUG::2016-03-18 17:26:47,448::vm::697::virt.vm::(_startUnderlyingVm) vmId=`ca440cf8-b140-46c1-8658-c2c71d0229cf`::Start
>Thread-13::INFO::2016-03-18 17:26:47,448::vm::1850::virt.vm::(_run) vmId=`ca440cf8-b140-46c1-8658-c2c71d0229cf`::VM wrapper has started
>Thread-13::DEBUG::2016-03-18 17:26:47,449::task::595::Storage.TaskManager.Task::(_updateState) Task=`031264f5-915b-4935-84ed-6c0bfbd1c8d9`::moving from state init -> state preparing
>Thread-13::INFO::2016-03-18 17:26:47,450::logUtils::48::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID=u'c1d2e073-fa2e-47a9-8a0c-3ceefad91685', spUUID=u'acc8b348-81f6-4bf2-9ffe-f1da755bb38d', imgUUID=u'e7e0392e-bcb9-4486-9e41-e163296528f5', volUUID=u'81610d39-bca1-4c94-b193-fae83a8a1912', options=None)
>Thread-13::DEBUG::2016-03-18 17:26:47,450::misc::750::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>MainThread::INFO::2016-03-18 17:27:02,446::vdsm::162::vds::(run) (PID: 20823) I am the actual vdsm 4.17.23.1-0.el7ev amd-4450b-4-1.englab.nay.redhat.com (3.10.0-363.el7.x86_64)
>MainThread::INFO::2016-03-18 17:27:02,447::vdsm::285::vds::(__set_cpu_affinity) VDSM will run with cpu affinity: frozenset([1])
>MainThread::DEBUG::2016-03-18 17:27:02,447::utils::671::root::(execCmd) /usr/bin/taskset --all-tasks --pid --cpu-list 1 20823 (cwd None)
>MainThread::DEBUG::2016-03-18 17:27:02,456::utils::689::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
>MainThread::DEBUG::2016-03-18 17:27:02,457::resourceManager::424::Storage.ResourceManager::(registerNamespace) Registering namespace 'Storage'
>MainThread::DEBUG::2016-03-18 17:27:02,458::threadPool::29::Storage.ThreadPool::(__init__) Enter - numThreads: 10, waitTimeout: 3, maxTasks: 500
>MainThread::DEBUG::2016-03-18 17:27:02,462::fileUtils::143::Storage.fileUtils::(createdir) Creating directory: /rhev/data-center/mnt mode: None
>MainThread::WARNING::2016-03-18 17:27:02,463::fileUtils::152::Storage.fileUtils::(createdir) Dir /rhev/data-center/mnt already exists
>MainThread::DEBUG::2016-03-18 17:27:02,478::sp::395::Storage.StoragePool::(cleanupMasterMount) master `/rhev/data-center/mnt/blockSD/c92de3f8-b279-489f-b69f-1b2e7bfdfccd/master` is not mounted, skipping
>MainThread::DEBUG::2016-03-18 17:27:02,555::hsm::409::Storage.Misc.excCmd::(__validateLvmLockingType) /usr/bin/taskset --cpu-list 0-1 /usr/bin/sudo -n /usr/sbin/lvm dumpconfig global/locking_type (cwd None)
>MainThread::DEBUG::2016-03-18 17:27:02,597::hsm::409::Storage.Misc.excCmd::(__validateLvmLockingType) SUCCESS: <err> = ''; <rc> = 0
>MainThread::DEBUG::2016-03-18 17:27:02,597::hsm::433::Storage.HSM::(__cleanStorageRepository) Started cleaning storage repository at '/rhev/data-center'
>MainThread::DEBUG::2016-03-18 17:27:02,601::hsm::465::Storage.HSM::(__cleanStorageRepository) White list: ['/rhev/data-center/hsm-tasks', '/rhev/data-center/hsm-tasks/*', '/rhev/data-center/mnt']
>MainThread::DEBUG::2016-03-18 17:27:02,601::hsm::466::Storage.HSM::(__cleanStorageRepository) Mount list: ['/rhev/data-center/mnt/10.73.194.27:_vol_S3_libvirtauto_yy_nfs1']
>MainThread::DEBUG::2016-03-18 17:27:02,601::hsm::468::Storage.HSM::(__cleanStorageRepository) Cleaning leftovers
>MainThread::DEBUG::2016-03-18 17:27:02,603::hsm::511::Storage.HSM::(__cleanStorageRepository) Finished cleaning storage repository at '/rhev/data-center'
>MainThread::INFO::2016-03-18 17:27:02,606::dispatcher::46::Storage.Dispatcher::(__init__) Starting StorageDispatcher...
>MainThread::DEBUG::2016-03-18 17:27:02,607::schedule::98::Scheduler::(start) Starting scheduler vdsm.Scheduler
>storageRefresh::DEBUG::2016-03-18 17:27:02,607::misc::750::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>storageRefresh::DEBUG::2016-03-18 17:27:02,608::misc::753::Storage.SamplingMethod::(__call__) Got in to sampling method
>storageRefresh::DEBUG::2016-03-18 17:27:02,608::misc::750::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>storageRefresh::DEBUG::2016-03-18 17:27:02,608::misc::753::Storage.SamplingMethod::(__call__) Got in to sampling method
>storageRefresh::DEBUG::2016-03-18 17:27:02,608::iscsi::434::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
>storageRefresh::DEBUG::2016-03-18 17:27:02,609::iscsiadm::97::Storage.Misc.excCmd::(_runCmd) /usr/bin/taskset --cpu-list 0-1 /usr/bin/sudo -n /sbin/iscsiadm -m session -R (cwd None)
>MainThread::DEBUG::2016-03-18 17:27:02,744::task::595::Storage.TaskManager.Task::(_updateState) Task=`ae4fea84-2c52-49fc-8b5d-dc721138e77d`::moving from state init -> state preparing
>MainThread::INFO::2016-03-18 17:27:02,744::logUtils::48::dispatcher::(wrapper) Run and protect: registerDomainStateChangeCallback(callbackFunc=<functools.partial object at 0x31e0050>)
>MainThread::INFO::2016-03-18 17:27:02,744::logUtils::51::dispatcher::(wrapper) Run and protect: registerDomainStateChangeCallback, Return response: None
>MainThread::DEBUG::2016-03-18 17:27:02,744::task::1191::Storage.TaskManager.Task::(prepare) Task=`ae4fea84-2c52-49fc-8b5d-dc721138e77d`::finished: None
>MainThread::DEBUG::2016-03-18 17:27:02,745::task::595::Storage.TaskManager.Task::(_updateState) Task=`ae4fea84-2c52-49fc-8b5d-dc721138e77d`::moving from state preparing -> state finished
>MainThread::DEBUG::2016-03-18 17:27:02,745::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>MainThread::DEBUG::2016-03-18 17:27:02,745::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>MainThread::DEBUG::2016-03-18 17:27:02,745::task::993::Storage.TaskManager.Task::(_decref) Task=`ae4fea84-2c52-49fc-8b5d-dc721138e77d`::ref 0 aborting False
>vdsm.Scheduler::DEBUG::2016-03-18 17:27:02,746::schedule::142::Scheduler::(_run) started
>storageRefresh::DEBUG::2016-03-18 17:27:02,747::misc::760::Storage.SamplingMethod::(__call__) Returning last result
>storageRefresh::DEBUG::2016-03-18 17:27:02,747::misc::750::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.hba.rescan)
>storageRefresh::DEBUG::2016-03-18 17:27:02,747::misc::753::Storage.SamplingMethod::(__call__) Got in to sampling method
>storageRefresh::DEBUG::2016-03-18 17:27:02,747::hba::56::Storage.HBA::(rescan) Starting scan
>storageRefresh::DEBUG::2016-03-18 17:27:02,747::supervdsm::76::SuperVdsmProxy::(_connect) Trying to connect to Super Vdsm
>MainThread::INFO::2016-03-18 17:27:02,749::momIF::46::MOM::(__init__) Preparing MOM interface
>MainThread::INFO::2016-03-18 17:27:02,751::momIF::55::MOM::(__init__) Using named unix socket /var/run/vdsm/mom-vdsm.sock
>MainThread::INFO::2016-03-18 17:27:02,753::secret::90::root::(clear) Unregistering all secrests
>MainThread::DEBUG::2016-03-18 17:27:02,753::libvirtconnection::161::root::(get) trying to connect libvirt
>MainThread::INFO::2016-03-18 17:27:02,785::vmchannels::211::vds::(settimeout) Setting channels' timeout to 30 seconds.
>clientIFinit::DEBUG::2016-03-18 17:27:02,786::clientIF::462::vds::(_recoverExistingVms) recovery: started
>MainThread::INFO::2016-03-18 17:27:02,792::protocoldetector::172::vds.MultiProtocolAcceptor::(__init__) Listening at 0.0.0.0:54321
>MainThread::DEBUG::2016-03-18 17:27:02,800::protocoldetector::199::vds.MultiProtocolAcceptor::(add_detector) Adding detector <rpc.bindingxmlrpc.XmlDetector instance at 0x329d950>
>VM Channels Listener::DEBUG::2016-03-18 17:27:02,911::vmchannels::193::vds::(run) Starting VM channels listener thread.
>MainThread::DEBUG::2016-03-18 17:27:02,911::protocoldetector::199::vds.MultiProtocolAcceptor::(add_detector) Adding detector <yajsonrpc.stompreactor.StompDetector instance at 0x3432c20>
>MainThread::DEBUG::2016-03-18 17:27:02,912::executor::69::Executor::(start) Starting executor
>MainThread::DEBUG::2016-03-18 17:27:02,912::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/0
>MainThread::DEBUG::2016-03-18 17:27:02,914::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/1
>jsonrpc.Executor/0::DEBUG::2016-03-18 17:27:02,914::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:27:02,915::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/2
>jsonrpc.Executor/1::DEBUG::2016-03-18 17:27:02,915::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:27:02,916::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/3
>jsonrpc.Executor/2::DEBUG::2016-03-18 17:27:02,916::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:27:02,923::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/4
>jsonrpc.Executor/3::DEBUG::2016-03-18 17:27:02,923::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:27:02,924::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/5
>jsonrpc.Executor/4::DEBUG::2016-03-18 17:27:02,924::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:27:02,925::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/6
>jsonrpc.Executor/5::DEBUG::2016-03-18 17:27:02,925::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:27:02,927::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/7
>jsonrpc.Executor/6::DEBUG::2016-03-18 17:27:02,928::executor::171::Executor::(_run) Worker started
>jsonrpc.Executor/7::DEBUG::2016-03-18 17:27:02,929::executor::171::Executor::(_run) Worker started
>BindingXMLRPC::INFO::2016-03-18 17:27:02,930::bindingxmlrpc::62::vds::(threaded_start) XMLRPC server running
>MainThread::DEBUG::2016-03-18 17:27:02,937::executor::69::Executor::(start) Starting executor
>MainThread::DEBUG::2016-03-18 17:27:02,938::executor::157::Executor::(__init__) Starting worker periodic/0
>MainThread::DEBUG::2016-03-18 17:27:02,939::executor::157::Executor::(__init__) Starting worker periodic/1
>periodic/0::DEBUG::2016-03-18 17:27:02,940::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:27:02,940::executor::157::Executor::(__init__) Starting worker periodic/2
>periodic/1::DEBUG::2016-03-18 17:27:02,941::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:27:02,942::executor::157::Executor::(__init__) Starting worker periodic/3
>periodic/2::DEBUG::2016-03-18 17:27:02,942::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:27:02,944::libvirtconnection::161::root::(get) trying to connect libvirt
>periodic/3::DEBUG::2016-03-18 17:27:02,945::executor::171::Executor::(_run) Worker started
>clientIFinit::DEBUG::2016-03-18 17:27:02,969::clientIF::575::vds::(_recoverVm) Trying to recover ca440cf8-b140-46c1-8658-c2c71d0229cf
>MainThread::DEBUG::2016-03-18 17:27:03,095::periodic::153::virt.periodic.Operation::(start) starting operation <VmDispatcher operation=<class 'virt.periodic.UpdateVolumes'> at 0x34533d0>
>MainThread::DEBUG::2016-03-18 17:27:03,096::periodic::153::virt.periodic.Operation::(start) starting operation <VmDispatcher operation=<class 'virt.periodic.NumaInfoMonitor'> at 0x3453710>
>MainThread::DEBUG::2016-03-18 17:27:03,096::periodic::153::virt.periodic.Operation::(start) starting operation <VmDispatcher operation=<class 'virt.periodic.BlockjobMonitor'> at 0x3453790>
>MainThread::DEBUG::2016-03-18 17:27:03,096::periodic::153::virt.periodic.Operation::(start) starting operation <VMBulkSampler at 0x3453810>
>MainThread::DEBUG::2016-03-18 17:27:03,097::periodic::153::virt.periodic.Operation::(start) starting operation <VmDispatcher operation=<class 'virt.periodic.DriveWatermarkMonitor'> at 0x34c0d50>
>periodic/1::WARNING::2016-03-18 17:27:03,130::periodic::285::virt.vm::(__call__) vmId=`ca440cf8-b140-46c1-8658-c2c71d0229cf`::could not run on ca440cf8-b140-46c1-8658-c2c71d0229cf: domain not connected
>periodic/2::WARNING::2016-03-18 17:27:03,131::periodic::258::virt.periodic.VmDispatcher::(__call__) could not run <class 'virt.periodic.BlockjobMonitor'> on [u'ca440cf8-b140-46c1-8658-c2c71d0229cf']
>clientIFinit::INFO::2016-03-18 17:27:03,134::clientIF::479::vds::(_recoverExistingVms) recovery [1:1/1]: recovered domain ca440cf8-b140-46c1-8658-c2c71d0229cf from libvirt
>clientIFinit::INFO::2016-03-18 17:27:03,134::clientIF::521::vds::(_recoverExistingVms) recovery: waiting for 1 domains to go up
>Thread-13::DEBUG::2016-03-18 17:27:03,134::vm::697::virt.vm::(_startUnderlyingVm) vmId=`ca440cf8-b140-46c1-8658-c2c71d0229cf`::Start
>Thread-13::INFO::2016-03-18 17:27:03,135::vm::1850::virt.vm::(_run) vmId=`ca440cf8-b140-46c1-8658-c2c71d0229cf`::VM wrapper has started
>Thread-13::DEBUG::2016-03-18 17:27:03,136::task::595::Storage.TaskManager.Task::(_updateState) Task=`6289a791-2d55-4a68-a513-6f9af19d6091`::moving from state init -> state preparing
>Thread-13::INFO::2016-03-18 17:27:03,136::logUtils::48::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID=u'c1d2e073-fa2e-47a9-8a0c-3ceefad91685', spUUID=u'acc8b348-81f6-4bf2-9ffe-f1da755bb38d', imgUUID=u'e7e0392e-bcb9-4486-9e41-e163296528f5', volUUID=u'81610d39-bca1-4c94-b193-fae83a8a1912', options=None)
>Thread-13::DEBUG::2016-03-18 17:27:03,137::misc::750::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>MainThread::INFO::2016-03-18 17:27:17,642::vdsm::162::vds::(run) (PID: 20995) I am the actual vdsm 4.17.23.1-0.el7ev amd-4450b-4-1.englab.nay.redhat.com (3.10.0-363.el7.x86_64)
>MainThread::INFO::2016-03-18 17:27:17,642::vdsm::285::vds::(__set_cpu_affinity) VDSM will run with cpu affinity: frozenset([1])
>MainThread::DEBUG::2016-03-18 17:27:17,643::utils::671::root::(execCmd) /usr/bin/taskset --all-tasks --pid --cpu-list 1 20995 (cwd None)
>MainThread::DEBUG::2016-03-18 17:27:17,649::utils::689::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
>MainThread::DEBUG::2016-03-18 17:27:17,650::resourceManager::424::Storage.ResourceManager::(registerNamespace) Registering namespace 'Storage'
>MainThread::DEBUG::2016-03-18 17:27:17,651::threadPool::29::Storage.ThreadPool::(__init__) Enter - numThreads: 10, waitTimeout: 3, maxTasks: 500
>MainThread::DEBUG::2016-03-18 17:27:17,655::fileUtils::143::Storage.fileUtils::(createdir) Creating directory: /rhev/data-center/mnt mode: None
>MainThread::WARNING::2016-03-18 17:27:17,655::fileUtils::152::Storage.fileUtils::(createdir) Dir /rhev/data-center/mnt already exists
>MainThread::DEBUG::2016-03-18 17:27:17,662::sp::395::Storage.StoragePool::(cleanupMasterMount) master `/rhev/data-center/mnt/blockSD/c92de3f8-b279-489f-b69f-1b2e7bfdfccd/master` is not mounted, skipping
>MainThread::DEBUG::2016-03-18 17:27:17,694::hsm::409::Storage.Misc.excCmd::(__validateLvmLockingType) /usr/bin/taskset --cpu-list 0-1 /usr/bin/sudo -n /usr/sbin/lvm dumpconfig global/locking_type (cwd None)
>MainThread::DEBUG::2016-03-18 17:27:17,728::hsm::409::Storage.Misc.excCmd::(__validateLvmLockingType) SUCCESS: <err> = ''; <rc> = 0
>MainThread::DEBUG::2016-03-18 17:27:17,728::hsm::433::Storage.HSM::(__cleanStorageRepository) Started cleaning storage repository at '/rhev/data-center'
>MainThread::DEBUG::2016-03-18 17:27:17,732::hsm::465::Storage.HSM::(__cleanStorageRepository) White list: ['/rhev/data-center/hsm-tasks', '/rhev/data-center/hsm-tasks/*', '/rhev/data-center/mnt']
>MainThread::DEBUG::2016-03-18 17:27:17,732::hsm::466::Storage.HSM::(__cleanStorageRepository) Mount list: ['/rhev/data-center/mnt/10.73.194.27:_vol_S3_libvirtauto_yy_nfs1']
>MainThread::DEBUG::2016-03-18 17:27:17,732::hsm::468::Storage.HSM::(__cleanStorageRepository) Cleaning leftovers
>MainThread::DEBUG::2016-03-18 17:27:17,734::hsm::511::Storage.HSM::(__cleanStorageRepository) Finished cleaning storage repository at '/rhev/data-center'
>MainThread::INFO::2016-03-18 17:27:17,737::dispatcher::46::Storage.Dispatcher::(__init__) Starting StorageDispatcher...
>MainThread::DEBUG::2016-03-18 17:27:17,738::schedule::98::Scheduler::(start) Starting scheduler vdsm.Scheduler
>storageRefresh::DEBUG::2016-03-18 17:27:17,738::misc::750::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>storageRefresh::DEBUG::2016-03-18 17:27:17,738::misc::753::Storage.SamplingMethod::(__call__) Got in to sampling method
>storageRefresh::DEBUG::2016-03-18 17:27:17,738::misc::750::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>storageRefresh::DEBUG::2016-03-18 17:27:17,739::misc::753::Storage.SamplingMethod::(__call__) Got in to sampling method
>storageRefresh::DEBUG::2016-03-18 17:27:17,739::iscsi::434::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
>storageRefresh::DEBUG::2016-03-18 17:27:17,739::iscsiadm::97::Storage.Misc.excCmd::(_runCmd) /usr/bin/taskset --cpu-list 0-1 /usr/bin/sudo -n /sbin/iscsiadm -m session -R (cwd None)
>MainThread::DEBUG::2016-03-18 17:27:17,845::task::595::Storage.TaskManager.Task::(_updateState) Task=`c8da2daa-6aaf-4be9-bbaa-d00b8b5ef75f`::moving from state init -> state preparing
>MainThread::INFO::2016-03-18 17:27:17,845::logUtils::48::dispatcher::(wrapper) Run and protect: registerDomainStateChangeCallback(callbackFunc=<functools.partial object at 0x2ce7050>)
>MainThread::INFO::2016-03-18 17:27:17,846::logUtils::51::dispatcher::(wrapper) Run and protect: registerDomainStateChangeCallback, Return response: None
>MainThread::DEBUG::2016-03-18 17:27:17,846::task::1191::Storage.TaskManager.Task::(prepare) Task=`c8da2daa-6aaf-4be9-bbaa-d00b8b5ef75f`::finished: None
>MainThread::DEBUG::2016-03-18 17:27:17,846::task::595::Storage.TaskManager.Task::(_updateState) Task=`c8da2daa-6aaf-4be9-bbaa-d00b8b5ef75f`::moving from state preparing -> state finished
>MainThread::DEBUG::2016-03-18 17:27:17,846::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>MainThread::DEBUG::2016-03-18 17:27:17,846::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>MainThread::DEBUG::2016-03-18 17:27:17,846::task::993::Storage.TaskManager.Task::(_decref) Task=`c8da2daa-6aaf-4be9-bbaa-d00b8b5ef75f`::ref 0 aborting False
>vdsm.Scheduler::DEBUG::2016-03-18 17:27:17,847::schedule::142::Scheduler::(_run) started
>storageRefresh::DEBUG::2016-03-18 17:27:17,848::misc::760::Storage.SamplingMethod::(__call__) Returning last result
>storageRefresh::DEBUG::2016-03-18 17:27:17,848::misc::750::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.hba.rescan)
>storageRefresh::DEBUG::2016-03-18 17:27:17,848::misc::753::Storage.SamplingMethod::(__call__) Got in to sampling method
>storageRefresh::DEBUG::2016-03-18 17:27:17,848::hba::56::Storage.HBA::(rescan) Starting scan
>storageRefresh::DEBUG::2016-03-18 17:27:17,849::supervdsm::76::SuperVdsmProxy::(_connect) Trying to connect to Super Vdsm
>MainThread::INFO::2016-03-18 17:27:17,851::momIF::46::MOM::(__init__) Preparing MOM interface
>MainThread::INFO::2016-03-18 17:27:17,853::momIF::55::MOM::(__init__) Using named unix socket /var/run/vdsm/mom-vdsm.sock
>MainThread::INFO::2016-03-18 17:27:17,854::secret::90::root::(clear) Unregistering all secrests
>MainThread::DEBUG::2016-03-18 17:27:17,855::libvirtconnection::161::root::(get) trying to connect libvirt
>MainThread::INFO::2016-03-18 17:27:17,878::vmchannels::211::vds::(settimeout) Setting channels' timeout to 30 seconds.
>clientIFinit::DEBUG::2016-03-18 17:27:17,879::clientIF::462::vds::(_recoverExistingVms) recovery: started
>MainThread::INFO::2016-03-18 17:27:17,881::protocoldetector::172::vds.MultiProtocolAcceptor::(__init__) Listening at 0.0.0.0:54321
>MainThread::DEBUG::2016-03-18 17:27:17,890::protocoldetector::199::vds.MultiProtocolAcceptor::(add_detector) Adding detector <rpc.bindingxmlrpc.XmlDetector instance at 0x2da19e0>
>VM Channels Listener::DEBUG::2016-03-18 17:27:18,004::vmchannels::193::vds::(run) Starting VM channels listener thread.
>MainThread::DEBUG::2016-03-18 17:27:18,005::protocoldetector::199::vds.MultiProtocolAcceptor::(add_detector) Adding detector <yajsonrpc.stompreactor.StompDetector instance at 0x2f38cb0>
>MainThread::DEBUG::2016-03-18 17:27:18,005::executor::69::Executor::(start) Starting executor
>MainThread::DEBUG::2016-03-18 17:27:18,006::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/0
>MainThread::DEBUG::2016-03-18 17:27:18,007::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/1
>jsonrpc.Executor/0::DEBUG::2016-03-18 17:27:18,008::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:27:18,008::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/2
>jsonrpc.Executor/1::DEBUG::2016-03-18 17:27:18,009::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:27:18,010::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/3
>jsonrpc.Executor/2::DEBUG::2016-03-18 17:27:18,010::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:27:18,011::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/4
>jsonrpc.Executor/3::DEBUG::2016-03-18 17:27:18,011::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:27:18,011::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/5
>jsonrpc.Executor/4::DEBUG::2016-03-18 17:27:18,012::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:27:18,013::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/6
>jsonrpc.Executor/5::DEBUG::2016-03-18 17:27:18,015::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:27:18,015::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/7
>jsonrpc.Executor/6::DEBUG::2016-03-18 17:27:18,016::executor::171::Executor::(_run) Worker started
>jsonrpc.Executor/7::DEBUG::2016-03-18 17:27:18,017::executor::171::Executor::(_run) Worker started
>BindingXMLRPC::INFO::2016-03-18 17:27:18,018::bindingxmlrpc::62::vds::(threaded_start) XMLRPC server running
>storageRefresh::DEBUG::2016-03-18 17:27:18,029::hba::62::Storage.HBA::(rescan) Scan finished
>storageRefresh::DEBUG::2016-03-18 17:27:18,030::misc::760::Storage.SamplingMethod::(__call__) Returning last result
>storageRefresh::DEBUG::2016-03-18 17:27:18,030::multipath::77::Storage.Misc.excCmd::(rescan) /usr/bin/taskset --cpu-list 0-1 /usr/bin/sudo -n /usr/sbin/multipath (cwd None)
>MainThread::DEBUG::2016-03-18 17:27:18,047::executor::69::Executor::(start) Starting executor
>MainThread::DEBUG::2016-03-18 17:27:18,048::executor::157::Executor::(__init__) Starting worker periodic/0
>MainThread::DEBUG::2016-03-18 17:27:18,050::executor::157::Executor::(__init__) Starting worker periodic/1
>periodic/0::DEBUG::2016-03-18 17:27:18,051::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:27:18,051::executor::157::Executor::(__init__) Starting worker periodic/2
>periodic/1::DEBUG::2016-03-18 17:27:18,052::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:27:18,052::executor::157::Executor::(__init__) Starting worker periodic/3
>periodic/2::DEBUG::2016-03-18 17:27:18,053::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:27:18,053::libvirtconnection::161::root::(get) trying to connect libvirt
>periodic/3::DEBUG::2016-03-18 17:27:18,054::executor::171::Executor::(_run) Worker started
>clientIFinit::DEBUG::2016-03-18 17:27:18,082::clientIF::575::vds::(_recoverVm) Trying to recover ca440cf8-b140-46c1-8658-c2c71d0229cf
>MainThread::DEBUG::2016-03-18 17:27:18,112::periodic::153::virt.periodic.Operation::(start) starting operation <VmDispatcher operation=<class 'virt.periodic.UpdateVolumes'> at 0x2f55710>
>MainThread::DEBUG::2016-03-18 17:27:18,113::periodic::153::virt.periodic.Operation::(start) starting operation <VmDispatcher operation=<class 'virt.periodic.NumaInfoMonitor'> at 0x2f55210>
>MainThread::DEBUG::2016-03-18 17:27:18,113::periodic::153::virt.periodic.Operation::(start) starting operation <VmDispatcher operation=<class 'virt.periodic.BlockjobMonitor'> at 0x2f55290>
>MainThread::DEBUG::2016-03-18 17:27:18,113::periodic::153::virt.periodic.Operation::(start) starting operation <VMBulkSampler at 0x2f55310>
>MainThread::DEBUG::2016-03-18 17:27:18,113::periodic::153::virt.periodic.Operation::(start) starting operation <VmDispatcher operation=<class 'virt.periodic.DriveWatermarkMonitor'> at 0x2fc7c90>
>MainThread::INFO::2016-03-18 17:27:32,643::vdsm::162::vds::(run) (PID: 21178) I am the actual vdsm 4.17.23.1-0.el7ev amd-4450b-4-1.englab.nay.redhat.com (3.10.0-363.el7.x86_64)
>MainThread::INFO::2016-03-18 17:27:32,644::vdsm::285::vds::(__set_cpu_affinity) VDSM will run with cpu affinity: frozenset([1])
>MainThread::DEBUG::2016-03-18 17:27:32,644::utils::671::root::(execCmd) /usr/bin/taskset --all-tasks --pid --cpu-list 1 21178 (cwd None)
>MainThread::DEBUG::2016-03-18 17:27:32,652::utils::689::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
>MainThread::DEBUG::2016-03-18 17:27:32,653::resourceManager::424::Storage.ResourceManager::(registerNamespace) Registering namespace 'Storage'
>MainThread::DEBUG::2016-03-18 17:27:32,654::threadPool::29::Storage.ThreadPool::(__init__) Enter - numThreads: 10, waitTimeout: 3, maxTasks: 500
>MainThread::DEBUG::2016-03-18 17:27:32,659::fileUtils::143::Storage.fileUtils::(createdir) Creating directory: /rhev/data-center/mnt mode: None
>MainThread::WARNING::2016-03-18 17:27:32,660::fileUtils::152::Storage.fileUtils::(createdir) Dir /rhev/data-center/mnt already exists
>MainThread::DEBUG::2016-03-18 17:27:32,667::sp::395::Storage.StoragePool::(cleanupMasterMount) master `/rhev/data-center/mnt/blockSD/c92de3f8-b279-489f-b69f-1b2e7bfdfccd/master` is not mounted, skipping
>MainThread::DEBUG::2016-03-18 17:27:32,710::hsm::409::Storage.Misc.excCmd::(__validateLvmLockingType) /usr/bin/taskset --cpu-list 0-1 /usr/bin/sudo -n /usr/sbin/lvm dumpconfig global/locking_type (cwd None)
>MainThread::DEBUG::2016-03-18 17:27:32,746::hsm::409::Storage.Misc.excCmd::(__validateLvmLockingType) SUCCESS: <err> = ''; <rc> = 0
>MainThread::DEBUG::2016-03-18 17:27:32,747::hsm::433::Storage.HSM::(__cleanStorageRepository) Started cleaning storage repository at '/rhev/data-center'
>MainThread::DEBUG::2016-03-18 17:27:32,750::hsm::465::Storage.HSM::(__cleanStorageRepository) White list: ['/rhev/data-center/hsm-tasks', '/rhev/data-center/hsm-tasks/*', '/rhev/data-center/mnt']
>MainThread::DEBUG::2016-03-18 17:27:32,750::hsm::466::Storage.HSM::(__cleanStorageRepository) Mount list: ['/rhev/data-center/mnt/10.73.194.27:_vol_S3_libvirtauto_yy_nfs1']
>MainThread::DEBUG::2016-03-18 17:27:32,750::hsm::468::Storage.HSM::(__cleanStorageRepository) Cleaning leftovers
>MainThread::DEBUG::2016-03-18 17:27:32,752::hsm::511::Storage.HSM::(__cleanStorageRepository) Finished cleaning storage repository at '/rhev/data-center'
>MainThread::INFO::2016-03-18 17:27:32,755::dispatcher::46::Storage.Dispatcher::(__init__) Starting StorageDispatcher...
>MainThread::DEBUG::2016-03-18 17:27:32,756::schedule::98::Scheduler::(start) Starting scheduler vdsm.Scheduler
>storageRefresh::DEBUG::2016-03-18 17:27:32,756::misc::750::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>storageRefresh::DEBUG::2016-03-18 17:27:32,757::misc::753::Storage.SamplingMethod::(__call__) Got in to sampling method
>storageRefresh::DEBUG::2016-03-18 17:27:32,757::misc::750::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>storageRefresh::DEBUG::2016-03-18 17:27:32,757::misc::753::Storage.SamplingMethod::(__call__) Got in to sampling method
>storageRefresh::DEBUG::2016-03-18 17:27:32,757::iscsi::434::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
>storageRefresh::DEBUG::2016-03-18 17:27:32,758::iscsiadm::97::Storage.Misc.excCmd::(_runCmd) /usr/bin/taskset --cpu-list 0-1 /usr/bin/sudo -n /sbin/iscsiadm -m session -R (cwd None)
>MainThread::DEBUG::2016-03-18 17:27:32,862::task::595::Storage.TaskManager.Task::(_updateState) Task=`9592c99a-652f-4140-8452-7ebaf8d5cfaa`::moving from state init -> state preparing
>MainThread::INFO::2016-03-18 17:27:32,863::logUtils::48::dispatcher::(wrapper) Run and protect: registerDomainStateChangeCallback(callbackFunc=<functools.partial object at 0x2165050>)
>MainThread::INFO::2016-03-18 17:27:32,863::logUtils::51::dispatcher::(wrapper) Run and protect: registerDomainStateChangeCallback, Return response: None
>MainThread::DEBUG::2016-03-18 17:27:32,863::task::1191::Storage.TaskManager.Task::(prepare) Task=`9592c99a-652f-4140-8452-7ebaf8d5cfaa`::finished: None
>MainThread::DEBUG::2016-03-18 17:27:32,863::task::595::Storage.TaskManager.Task::(_updateState) Task=`9592c99a-652f-4140-8452-7ebaf8d5cfaa`::moving from state preparing -> state finished
>MainThread::DEBUG::2016-03-18 17:27:32,864::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>MainThread::DEBUG::2016-03-18 17:27:32,864::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>MainThread::DEBUG::2016-03-18 17:27:32,864::task::993::Storage.TaskManager.Task::(_decref) Task=`9592c99a-652f-4140-8452-7ebaf8d5cfaa`::ref 0 aborting False
>vdsm.Scheduler::DEBUG::2016-03-18 17:27:32,865::schedule::142::Scheduler::(_run) started
>MainThread::INFO::2016-03-18 17:27:32,866::momIF::46::MOM::(__init__) Preparing MOM interface
>MainThread::INFO::2016-03-18 17:27:32,867::momIF::55::MOM::(__init__) Using named unix socket /var/run/vdsm/mom-vdsm.sock
>MainThread::INFO::2016-03-18 17:27:32,869::secret::90::root::(clear) Unregistering all secrests
>MainThread::DEBUG::2016-03-18 17:27:32,869::libvirtconnection::161::root::(get) trying to connect libvirt
>storageRefresh::DEBUG::2016-03-18 17:27:32,882::misc::760::Storage.SamplingMethod::(__call__) Returning last result
>storageRefresh::DEBUG::2016-03-18 17:27:32,882::misc::750::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.hba.rescan)
>storageRefresh::DEBUG::2016-03-18 17:27:32,882::misc::753::Storage.SamplingMethod::(__call__) Got in to sampling method
>storageRefresh::DEBUG::2016-03-18 17:27:32,883::hba::56::Storage.HBA::(rescan) Starting scan
>storageRefresh::DEBUG::2016-03-18 17:27:32,884::supervdsm::76::SuperVdsmProxy::(_connect) Trying to connect to Super Vdsm
>MainThread::INFO::2016-03-18 17:27:32,898::vmchannels::211::vds::(settimeout) Setting channels' timeout to 30 seconds.
>clientIFinit::DEBUG::2016-03-18 17:27:32,899::clientIF::462::vds::(_recoverExistingVms) recovery: started
>MainThread::INFO::2016-03-18 17:27:32,902::protocoldetector::172::vds.MultiProtocolAcceptor::(__init__) Listening at 0.0.0.0:54321
>MainThread::DEBUG::2016-03-18 17:27:32,911::protocoldetector::199::vds.MultiProtocolAcceptor::(add_detector) Adding detector <rpc.bindingxmlrpc.XmlDetector instance at 0x221eab8>
>VM Channels Listener::DEBUG::2016-03-18 17:27:33,024::vmchannels::193::vds::(run) Starting VM channels listener thread.
>MainThread::DEBUG::2016-03-18 17:27:33,030::protocoldetector::199::vds.MultiProtocolAcceptor::(add_detector) Adding detector <yajsonrpc.stompreactor.StompDetector instance at 0x2046950>
>MainThread::DEBUG::2016-03-18 17:27:33,031::executor::69::Executor::(start) Starting executor
>MainThread::DEBUG::2016-03-18 17:27:33,031::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/0
>MainThread::DEBUG::2016-03-18 17:27:33,032::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/1
>jsonrpc.Executor/0::DEBUG::2016-03-18 17:27:33,032::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:27:33,033::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/2
>jsonrpc.Executor/1::DEBUG::2016-03-18 17:27:33,033::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:27:33,034::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/3
>jsonrpc.Executor/2::DEBUG::2016-03-18 17:27:33,034::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:27:33,035::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/4
>jsonrpc.Executor/3::DEBUG::2016-03-18 17:27:33,035::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:27:33,036::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/5
>jsonrpc.Executor/4::DEBUG::2016-03-18 17:27:33,036::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:27:33,037::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/6
>jsonrpc.Executor/5::DEBUG::2016-03-18 17:27:33,038::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:27:33,039::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/7
>jsonrpc.Executor/6::DEBUG::2016-03-18 17:27:33,039::executor::171::Executor::(_run) Worker started
>jsonrpc.Executor/7::DEBUG::2016-03-18 17:27:33,040::executor::171::Executor::(_run) Worker started
>BindingXMLRPC::INFO::2016-03-18 17:27:33,041::bindingxmlrpc::62::vds::(threaded_start) XMLRPC server running
>MainThread::DEBUG::2016-03-18 17:27:33,052::executor::69::Executor::(start) Starting executor
>MainThread::DEBUG::2016-03-18 17:27:33,053::executor::157::Executor::(__init__) Starting worker periodic/0
>MainThread::DEBUG::2016-03-18 17:27:33,053::executor::157::Executor::(__init__) Starting worker periodic/1
>periodic/0::DEBUG::2016-03-18 17:27:33,054::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:27:33,054::executor::157::Executor::(__init__) Starting worker periodic/2
>periodic/1::DEBUG::2016-03-18 17:27:33,055::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:27:33,055::executor::157::Executor::(__init__) Starting worker periodic/3
>periodic/2::DEBUG::2016-03-18 17:27:33,056::executor::171::Executor::(_run) Worker started
>clientIFinit::DEBUG::2016-03-18 17:27:33,063::clientIF::575::vds::(_recoverVm) Trying to recover ca440cf8-b140-46c1-8658-c2c71d0229cf
>MainThread::DEBUG::2016-03-18 17:27:33,064::libvirtconnection::161::root::(get) trying to connect libvirt
>periodic/3::DEBUG::2016-03-18 17:27:33,065::executor::171::Executor::(_run) Worker started
>storageRefresh::DEBUG::2016-03-18 17:27:33,068::hba::62::Storage.HBA::(rescan) Scan finished
>storageRefresh::DEBUG::2016-03-18 17:27:33,068::misc::760::Storage.SamplingMethod::(__call__) Returning last result
>storageRefresh::DEBUG::2016-03-18 17:27:33,069::multipath::77::Storage.Misc.excCmd::(rescan) /usr/bin/taskset --cpu-list 0-1 /usr/bin/sudo -n /usr/sbin/multipath (cwd None)
>MainThread::DEBUG::2016-03-18 17:27:33,125::periodic::153::virt.periodic.Operation::(start) starting operation <VmDispatcher operation=<class 'virt.periodic.UpdateVolumes'> at 0x7f891400c510>
>MainThread::DEBUG::2016-03-18 17:27:33,125::periodic::153::virt.periodic.Operation::(start) starting operation <VmDispatcher operation=<class 'virt.periodic.NumaInfoMonitor'> at 0x7f8914011910>
>MainThread::DEBUG::2016-03-18 17:27:33,125::periodic::153::virt.periodic.Operation::(start) starting operation <VmDispatcher operation=<class 'virt.periodic.BlockjobMonitor'> at 0x7f8914011990>
>MainThread::DEBUG::2016-03-18 17:27:33,126::periodic::153::virt.periodic.Operation::(start) starting operation <VMBulkSampler at 0x7f8914011a10>
>MainThread::DEBUG::2016-03-18 17:27:33,126::periodic::153::virt.periodic.Operation::(start) starting operation <VmDispatcher operation=<class 'virt.periodic.DriveWatermarkMonitor'> at 0x7f891401e350>
>periodic/0::WARNING::2016-03-18 17:27:33,131::periodic::258::virt.periodic.VmDispatcher::(__call__) could not run <class 'virt.periodic.BlockjobMonitor'> on [u'ca440cf8-b140-46c1-8658-c2c71d0229cf']
>periodic/1::WARNING::2016-03-18 17:27:33,132::periodic::285::virt.vm::(__call__) vmId=`ca440cf8-b140-46c1-8658-c2c71d0229cf`::could not run on ca440cf8-b140-46c1-8658-c2c71d0229cf: domain not connected
>clientIFinit::INFO::2016-03-18 17:27:33,134::clientIF::479::vds::(_recoverExistingVms) recovery [1:1/1]: recovered domain ca440cf8-b140-46c1-8658-c2c71d0229cf from libvirt
>clientIFinit::INFO::2016-03-18 17:27:33,135::clientIF::521::vds::(_recoverExistingVms) recovery: waiting for 1 domains to go up
>Thread-13::DEBUG::2016-03-18 17:27:33,135::vm::697::virt.vm::(_startUnderlyingVm) vmId=`ca440cf8-b140-46c1-8658-c2c71d0229cf`::Start
>Thread-13::INFO::2016-03-18 17:27:33,136::vm::1850::virt.vm::(_run) vmId=`ca440cf8-b140-46c1-8658-c2c71d0229cf`::VM wrapper has started
>Thread-13::DEBUG::2016-03-18 17:27:33,137::task::595::Storage.TaskManager.Task::(_updateState) Task=`57bdcc38-0625-401f-b491-78d97e5a339f`::moving from state init -> state preparing
>Thread-13::INFO::2016-03-18 17:27:33,138::logUtils::48::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID=u'c1d2e073-fa2e-47a9-8a0c-3ceefad91685', spUUID=u'acc8b348-81f6-4bf2-9ffe-f1da755bb38d', imgUUID=u'e7e0392e-bcb9-4486-9e41-e163296528f5', volUUID=u'81610d39-bca1-4c94-b193-fae83a8a1912', options=None)
>Thread-13::DEBUG::2016-03-18 17:27:33,139::misc::750::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>MainThread::INFO::2016-03-18 17:27:47,660::vdsm::162::vds::(run) (PID: 21358) I am the actual vdsm 4.17.23.1-0.el7ev amd-4450b-4-1.englab.nay.redhat.com (3.10.0-363.el7.x86_64)
>MainThread::INFO::2016-03-18 17:27:47,660::vdsm::285::vds::(__set_cpu_affinity) VDSM will run with cpu affinity: frozenset([1])
>MainThread::DEBUG::2016-03-18 17:27:47,661::utils::671::root::(execCmd) /usr/bin/taskset --all-tasks --pid --cpu-list 1 21358 (cwd None)
>MainThread::DEBUG::2016-03-18 17:27:47,667::utils::689::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
>MainThread::DEBUG::2016-03-18 17:27:47,669::resourceManager::424::Storage.ResourceManager::(registerNamespace) Registering namespace 'Storage'
>MainThread::DEBUG::2016-03-18 17:27:47,669::threadPool::29::Storage.ThreadPool::(__init__) Enter - numThreads: 10, waitTimeout: 3, maxTasks: 500
>MainThread::DEBUG::2016-03-18 17:27:47,677::fileUtils::143::Storage.fileUtils::(createdir) Creating directory: /rhev/data-center/mnt mode: None
>MainThread::WARNING::2016-03-18 17:27:47,677::fileUtils::152::Storage.fileUtils::(createdir) Dir /rhev/data-center/mnt already exists
>MainThread::DEBUG::2016-03-18 17:27:47,683::sp::395::Storage.StoragePool::(cleanupMasterMount) master `/rhev/data-center/mnt/blockSD/c92de3f8-b279-489f-b69f-1b2e7bfdfccd/master` is not mounted, skipping
>MainThread::DEBUG::2016-03-18 17:27:47,727::hsm::409::Storage.Misc.excCmd::(__validateLvmLockingType) /usr/bin/taskset --cpu-list 0-1 /usr/bin/sudo -n /usr/sbin/lvm dumpconfig global/locking_type (cwd None)
>MainThread::DEBUG::2016-03-18 17:27:47,760::hsm::409::Storage.Misc.excCmd::(__validateLvmLockingType) SUCCESS: <err> = ''; <rc> = 0
>MainThread::DEBUG::2016-03-18 17:27:47,760::hsm::433::Storage.HSM::(__cleanStorageRepository) Started cleaning storage repository at '/rhev/data-center'
>MainThread::DEBUG::2016-03-18 17:27:47,763::hsm::465::Storage.HSM::(__cleanStorageRepository) White list: ['/rhev/data-center/hsm-tasks', '/rhev/data-center/hsm-tasks/*', '/rhev/data-center/mnt']
>MainThread::DEBUG::2016-03-18 17:27:47,764::hsm::466::Storage.HSM::(__cleanStorageRepository) Mount list: ['/rhev/data-center/mnt/10.73.194.27:_vol_S3_libvirtauto_yy_nfs1']
>MainThread::DEBUG::2016-03-18 17:27:47,764::hsm::468::Storage.HSM::(__cleanStorageRepository) Cleaning leftovers
>MainThread::DEBUG::2016-03-18 17:27:47,766::hsm::511::Storage.HSM::(__cleanStorageRepository) Finished cleaning storage repository at '/rhev/data-center'
>MainThread::INFO::2016-03-18 17:27:47,769::dispatcher::46::Storage.Dispatcher::(__init__) Starting StorageDispatcher...
>MainThread::DEBUG::2016-03-18 17:27:47,769::schedule::98::Scheduler::(start) Starting scheduler vdsm.Scheduler
>storageRefresh::DEBUG::2016-03-18 17:27:47,770::misc::750::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>storageRefresh::DEBUG::2016-03-18 17:27:47,770::misc::753::Storage.SamplingMethod::(__call__) Got in to sampling method
>storageRefresh::DEBUG::2016-03-18 17:27:47,770::misc::750::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>storageRefresh::DEBUG::2016-03-18 17:27:47,771::misc::753::Storage.SamplingMethod::(__call__) Got in to sampling method
>storageRefresh::DEBUG::2016-03-18 17:27:47,771::iscsi::434::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
>storageRefresh::DEBUG::2016-03-18 17:27:47,771::iscsiadm::97::Storage.Misc.excCmd::(_runCmd) /usr/bin/taskset --cpu-list 0-1 /usr/bin/sudo -n /sbin/iscsiadm -m session -R (cwd None)
>MainThread::DEBUG::2016-03-18 17:27:47,877::task::595::Storage.TaskManager.Task::(_updateState) Task=`0c024c64-5479-4f3f-9f2f-530afb605c8f`::moving from state init -> state preparing
>MainThread::INFO::2016-03-18 17:27:47,878::logUtils::48::dispatcher::(wrapper) Run and protect: registerDomainStateChangeCallback(callbackFunc=<functools.partial object at 0x2960050>)
>MainThread::INFO::2016-03-18 17:27:47,878::logUtils::51::dispatcher::(wrapper) Run and protect: registerDomainStateChangeCallback, Return response: None
>MainThread::DEBUG::2016-03-18 17:27:47,878::task::1191::Storage.TaskManager.Task::(prepare) Task=`0c024c64-5479-4f3f-9f2f-530afb605c8f`::finished: None
>MainThread::DEBUG::2016-03-18 17:27:47,878::task::595::Storage.TaskManager.Task::(_updateState) Task=`0c024c64-5479-4f3f-9f2f-530afb605c8f`::moving from state preparing -> state finished
>MainThread::DEBUG::2016-03-18 17:27:47,878::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>MainThread::DEBUG::2016-03-18 17:27:47,879::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>MainThread::DEBUG::2016-03-18 17:27:47,879::task::993::Storage.TaskManager.Task::(_decref) Task=`0c024c64-5479-4f3f-9f2f-530afb605c8f`::ref 0 aborting False
>vdsm.Scheduler::DEBUG::2016-03-18 17:27:47,880::schedule::142::Scheduler::(_run) started
>storageRefresh::DEBUG::2016-03-18 17:27:47,880::misc::760::Storage.SamplingMethod::(__call__) Returning last result
>storageRefresh::DEBUG::2016-03-18 17:27:47,881::misc::750::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.hba.rescan)
>storageRefresh::DEBUG::2016-03-18 17:27:47,881::misc::753::Storage.SamplingMethod::(__call__) Got in to sampling method
>storageRefresh::DEBUG::2016-03-18 17:27:47,881::hba::56::Storage.HBA::(rescan) Starting scan
>storageRefresh::DEBUG::2016-03-18 17:27:47,881::supervdsm::76::SuperVdsmProxy::(_connect) Trying to connect to Super Vdsm
>MainThread::INFO::2016-03-18 17:27:47,883::momIF::46::MOM::(__init__) Preparing MOM interface
>MainThread::INFO::2016-03-18 17:27:47,886::momIF::55::MOM::(__init__) Using named unix socket /var/run/vdsm/mom-vdsm.sock
>MainThread::INFO::2016-03-18 17:27:47,887::secret::90::root::(clear) Unregistering all secrests
>MainThread::DEBUG::2016-03-18 17:27:47,887::libvirtconnection::161::root::(get) trying to connect libvirt
>MainThread::INFO::2016-03-18 17:27:47,915::vmchannels::211::vds::(settimeout) Setting channels' timeout to 30 seconds.
>clientIFinit::DEBUG::2016-03-18 17:27:47,915::clientIF::462::vds::(_recoverExistingVms) recovery: started
>MainThread::INFO::2016-03-18 17:27:47,924::protocoldetector::172::vds.MultiProtocolAcceptor::(__init__) Listening at 0.0.0.0:54321
>MainThread::DEBUG::2016-03-18 17:27:47,932::protocoldetector::199::vds.MultiProtocolAcceptor::(add_detector) Adding detector <rpc.bindingxmlrpc.XmlDetector instance at 0x2a1a9e0>
>VM Channels Listener::DEBUG::2016-03-18 17:27:48,045::vmchannels::193::vds::(run) Starting VM channels listener thread.
>MainThread::DEBUG::2016-03-18 17:27:48,051::protocoldetector::199::vds.MultiProtocolAcceptor::(add_detector) Adding detector <yajsonrpc.stompreactor.StompDetector instance at 0x2843950>
>MainThread::DEBUG::2016-03-18 17:27:48,052::executor::69::Executor::(start) Starting executor
>MainThread::DEBUG::2016-03-18 17:27:48,052::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/0
>MainThread::DEBUG::2016-03-18 17:27:48,053::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/1
>jsonrpc.Executor/0::DEBUG::2016-03-18 17:27:48,054::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:27:48,054::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/2
>jsonrpc.Executor/1::DEBUG::2016-03-18 17:27:48,055::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:27:48,055::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/3
>jsonrpc.Executor/2::DEBUG::2016-03-18 17:27:48,055::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:27:48,056::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/4
>jsonrpc.Executor/3::DEBUG::2016-03-18 17:27:48,057::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:27:48,057::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/5
>jsonrpc.Executor/4::DEBUG::2016-03-18 17:27:48,058::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:27:48,058::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/6
>jsonrpc.Executor/5::DEBUG::2016-03-18 17:27:48,058::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:27:48,059::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/7
>storageRefresh::DEBUG::2016-03-18 17:27:48,067::hba::62::Storage.HBA::(rescan) Scan finished
>storageRefresh::DEBUG::2016-03-18 17:27:48,068::misc::760::Storage.SamplingMethod::(__call__) Returning last result
>storageRefresh::DEBUG::2016-03-18 17:27:48,068::multipath::77::Storage.Misc.excCmd::(rescan) /usr/bin/taskset --cpu-list 0-1 /usr/bin/sudo -n /usr/sbin/multipath (cwd None)
>jsonrpc.Executor/6::DEBUG::2016-03-18 17:27:48,081::executor::171::Executor::(_run) Worker started
>jsonrpc.Executor/7::DEBUG::2016-03-18 17:27:48,082::executor::171::Executor::(_run) Worker started
>clientIFinit::DEBUG::2016-03-18 17:27:48,090::clientIF::575::vds::(_recoverVm) Trying to recover ca440cf8-b140-46c1-8658-c2c71d0229cf
>BindingXMLRPC::INFO::2016-03-18 17:27:48,092::bindingxmlrpc::62::vds::(threaded_start) XMLRPC server running
>MainThread::DEBUG::2016-03-18 17:27:48,093::executor::69::Executor::(start) Starting executor
>MainThread::DEBUG::2016-03-18 17:27:48,094::executor::157::Executor::(__init__) Starting worker periodic/0
>MainThread::DEBUG::2016-03-18 17:27:48,095::executor::157::Executor::(__init__) Starting worker periodic/1
>periodic/0::DEBUG::2016-03-18 17:27:48,095::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:27:48,096::executor::157::Executor::(__init__) Starting worker periodic/2
>periodic/1::DEBUG::2016-03-18 17:27:48,096::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:27:48,096::executor::157::Executor::(__init__) Starting worker periodic/3
>periodic/2::DEBUG::2016-03-18 17:27:48,097::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:27:48,097::libvirtconnection::161::root::(get) trying to connect libvirt
>periodic/3::DEBUG::2016-03-18 17:27:48,098::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:27:48,133::periodic::153::virt.periodic.Operation::(start) starting operation <VmDispatcher operation=<class 'virt.periodic.UpdateVolumes'> at 0x7f98d800d850>
>MainThread::DEBUG::2016-03-18 17:27:48,134::periodic::153::virt.periodic.Operation::(start) starting operation <VmDispatcher operation=<class 'virt.periodic.NumaInfoMonitor'> at 0x7f98d800da90>
>MainThread::DEBUG::2016-03-18 17:27:48,134::periodic::153::virt.periodic.Operation::(start) starting operation <VmDispatcher operation=<class 'virt.periodic.BlockjobMonitor'> at 0x7f98d800db10>
>MainThread::DEBUG::2016-03-18 17:27:48,134::periodic::153::virt.periodic.Operation::(start) starting operation <VMBulkSampler at 0x7f98d800db90>
>MainThread::DEBUG::2016-03-18 17:27:48,134::periodic::153::virt.periodic.Operation::(start) starting operation <VmDispatcher operation=<class 'virt.periodic.DriveWatermarkMonitor'> at 0x7f98d8010550>
>periodic/0::WARNING::2016-03-18 17:27:48,140::periodic::258::virt.periodic.VmDispatcher::(__call__) could not run <class 'virt.periodic.BlockjobMonitor'> on [u'ca440cf8-b140-46c1-8658-c2c71d0229cf']
>periodic/1::WARNING::2016-03-18 17:27:48,141::periodic::285::virt.vm::(__call__) vmId=`ca440cf8-b140-46c1-8658-c2c71d0229cf`::could not run on ca440cf8-b140-46c1-8658-c2c71d0229cf: domain not connected
>clientIFinit::INFO::2016-03-18 17:27:48,142::clientIF::479::vds::(_recoverExistingVms) recovery [1:1/1]: recovered domain ca440cf8-b140-46c1-8658-c2c71d0229cf from libvirt
>clientIFinit::INFO::2016-03-18 17:27:48,143::clientIF::521::vds::(_recoverExistingVms) recovery: waiting for 1 domains to go up
>Thread-13::DEBUG::2016-03-18 17:27:48,143::vm::697::virt.vm::(_startUnderlyingVm) vmId=`ca440cf8-b140-46c1-8658-c2c71d0229cf`::Start
>Thread-13::INFO::2016-03-18 17:27:48,143::vm::1850::virt.vm::(_run) vmId=`ca440cf8-b140-46c1-8658-c2c71d0229cf`::VM wrapper has started
>Thread-13::DEBUG::2016-03-18 17:27:48,145::task::595::Storage.TaskManager.Task::(_updateState) Task=`154e43b9-dc2d-4d29-b138-587a56ef2a89`::moving from state init -> state preparing
>Thread-13::INFO::2016-03-18 17:27:48,145::logUtils::48::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID=u'c1d2e073-fa2e-47a9-8a0c-3ceefad91685', spUUID=u'acc8b348-81f6-4bf2-9ffe-f1da755bb38d', imgUUID=u'e7e0392e-bcb9-4486-9e41-e163296528f5', volUUID=u'81610d39-bca1-4c94-b193-fae83a8a1912', options=None)
>Thread-13::DEBUG::2016-03-18 17:27:48,146::misc::750::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>MainThread::INFO::2016-03-18 17:28:02,722::vdsm::162::vds::(run) (PID: 21541) I am the actual vdsm 4.17.23.1-0.el7ev amd-4450b-4-1.englab.nay.redhat.com (3.10.0-363.el7.x86_64)
>MainThread::INFO::2016-03-18 17:28:02,723::vdsm::285::vds::(__set_cpu_affinity) VDSM will run with cpu affinity: frozenset([1])
>MainThread::DEBUG::2016-03-18 17:28:02,724::utils::671::root::(execCmd) /usr/bin/taskset --all-tasks --pid --cpu-list 1 21541 (cwd None)
>MainThread::DEBUG::2016-03-18 17:28:02,730::utils::689::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
>MainThread::DEBUG::2016-03-18 17:28:02,732::resourceManager::424::Storage.ResourceManager::(registerNamespace) Registering namespace 'Storage'
>MainThread::DEBUG::2016-03-18 17:28:02,732::threadPool::29::Storage.ThreadPool::(__init__) Enter - numThreads: 10, waitTimeout: 3, maxTasks: 500
>MainThread::DEBUG::2016-03-18 17:28:02,739::fileUtils::143::Storage.fileUtils::(createdir) Creating directory: /rhev/data-center/mnt mode: None
>MainThread::WARNING::2016-03-18 17:28:02,739::fileUtils::152::Storage.fileUtils::(createdir) Dir /rhev/data-center/mnt already exists
>MainThread::DEBUG::2016-03-18 17:28:02,746::sp::395::Storage.StoragePool::(cleanupMasterMount) master `/rhev/data-center/mnt/blockSD/c92de3f8-b279-489f-b69f-1b2e7bfdfccd/master` is not mounted, skipping
>MainThread::DEBUG::2016-03-18 17:28:02,793::hsm::409::Storage.Misc.excCmd::(__validateLvmLockingType) /usr/bin/taskset --cpu-list 0-1 /usr/bin/sudo -n /usr/sbin/lvm dumpconfig global/locking_type (cwd None)
>MainThread::DEBUG::2016-03-18 17:28:02,827::hsm::409::Storage.Misc.excCmd::(__validateLvmLockingType) SUCCESS: <err> = ''; <rc> = 0
>MainThread::DEBUG::2016-03-18 17:28:02,828::hsm::433::Storage.HSM::(__cleanStorageRepository) Started cleaning storage repository at '/rhev/data-center'
>MainThread::DEBUG::2016-03-18 17:28:02,831::hsm::465::Storage.HSM::(__cleanStorageRepository) White list: ['/rhev/data-center/hsm-tasks', '/rhev/data-center/hsm-tasks/*', '/rhev/data-center/mnt']
>MainThread::DEBUG::2016-03-18 17:28:02,832::hsm::466::Storage.HSM::(__cleanStorageRepository) Mount list: ['/rhev/data-center/mnt/10.73.194.27:_vol_S3_libvirtauto_yy_nfs1']
>MainThread::DEBUG::2016-03-18 17:28:02,832::hsm::468::Storage.HSM::(__cleanStorageRepository) Cleaning leftovers
>MainThread::DEBUG::2016-03-18 17:28:02,834::hsm::511::Storage.HSM::(__cleanStorageRepository) Finished cleaning storage repository at '/rhev/data-center'
>MainThread::INFO::2016-03-18 17:28:02,837::dispatcher::46::Storage.Dispatcher::(__init__) Starting StorageDispatcher...
>MainThread::DEBUG::2016-03-18 17:28:02,837::schedule::98::Scheduler::(start) Starting scheduler vdsm.Scheduler
>storageRefresh::DEBUG::2016-03-18 17:28:02,838::misc::750::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>storageRefresh::DEBUG::2016-03-18 17:28:02,838::misc::753::Storage.SamplingMethod::(__call__) Got in to sampling method
>storageRefresh::DEBUG::2016-03-18 17:28:02,838::misc::750::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>storageRefresh::DEBUG::2016-03-18 17:28:02,838::misc::753::Storage.SamplingMethod::(__call__) Got in to sampling method
>storageRefresh::DEBUG::2016-03-18 17:28:02,838::iscsi::434::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
>storageRefresh::DEBUG::2016-03-18 17:28:02,839::iscsiadm::97::Storage.Misc.excCmd::(_runCmd) /usr/bin/taskset --cpu-list 0-1 /usr/bin/sudo -n /sbin/iscsiadm -m session -R (cwd None)
>MainThread::DEBUG::2016-03-18 17:28:02,944::task::595::Storage.TaskManager.Task::(_updateState) Task=`1a08c369-ed24-42ff-b4f0-355a447c627a`::moving from state init -> state preparing
>MainThread::INFO::2016-03-18 17:28:02,944::logUtils::48::dispatcher::(wrapper) Run and protect: registerDomainStateChangeCallback(callbackFunc=<functools.partial object at 0x223a050>)
>MainThread::INFO::2016-03-18 17:28:02,945::logUtils::51::dispatcher::(wrapper) Run and protect: registerDomainStateChangeCallback, Return response: None
>MainThread::DEBUG::2016-03-18 17:28:02,945::task::1191::Storage.TaskManager.Task::(prepare) Task=`1a08c369-ed24-42ff-b4f0-355a447c627a`::finished: None
>MainThread::DEBUG::2016-03-18 17:28:02,945::task::595::Storage.TaskManager.Task::(_updateState) Task=`1a08c369-ed24-42ff-b4f0-355a447c627a`::moving from state preparing -> state finished
>MainThread::DEBUG::2016-03-18 17:28:02,945::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>MainThread::DEBUG::2016-03-18 17:28:02,945::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>MainThread::DEBUG::2016-03-18 17:28:02,946::task::993::Storage.TaskManager.Task::(_decref) Task=`1a08c369-ed24-42ff-b4f0-355a447c627a`::ref 0 aborting False
>vdsm.Scheduler::DEBUG::2016-03-18 17:28:02,946::schedule::142::Scheduler::(_run) started
>storageRefresh::DEBUG::2016-03-18 17:28:02,947::misc::760::Storage.SamplingMethod::(__call__) Returning last result
>storageRefresh::DEBUG::2016-03-18 17:28:02,947::misc::750::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.hba.rescan)
>storageRefresh::DEBUG::2016-03-18 17:28:02,947::misc::753::Storage.SamplingMethod::(__call__) Got in to sampling method
>storageRefresh::DEBUG::2016-03-18 17:28:02,948::hba::56::Storage.HBA::(rescan) Starting scan
>storageRefresh::DEBUG::2016-03-18 17:28:02,948::supervdsm::76::SuperVdsmProxy::(_connect) Trying to connect to Super Vdsm
>MainThread::INFO::2016-03-18 17:28:02,950::momIF::46::MOM::(__init__) Preparing MOM interface
>MainThread::INFO::2016-03-18 17:28:02,952::momIF::55::MOM::(__init__) Using named unix socket /var/run/vdsm/mom-vdsm.sock
>MainThread::INFO::2016-03-18 17:28:02,953::secret::90::root::(clear) Unregistering all secrests
>MainThread::DEBUG::2016-03-18 17:28:02,954::libvirtconnection::161::root::(get) trying to connect libvirt
>MainThread::INFO::2016-03-18 17:28:02,986::vmchannels::211::vds::(settimeout) Setting channels' timeout to 30 seconds.
>clientIFinit::DEBUG::2016-03-18 17:28:02,988::clientIF::462::vds::(_recoverExistingVms) recovery: started
>MainThread::INFO::2016-03-18 17:28:02,991::protocoldetector::172::vds.MultiProtocolAcceptor::(__init__) Listening at 0.0.0.0:54321
>MainThread::DEBUG::2016-03-18 17:28:03,000::protocoldetector::199::vds.MultiProtocolAcceptor::(add_detector) Adding detector <rpc.bindingxmlrpc.XmlDetector instance at 0x22f49e0>
>VM Channels Listener::DEBUG::2016-03-18 17:28:03,113::vmchannels::193::vds::(run) Starting VM channels listener thread.
>MainThread::DEBUG::2016-03-18 17:28:03,113::protocoldetector::199::vds.MultiProtocolAcceptor::(add_detector) Adding detector <yajsonrpc.stompreactor.StompDetector instance at 0x248ccb0>
>MainThread::DEBUG::2016-03-18 17:28:03,113::executor::69::Executor::(start) Starting executor
>MainThread::DEBUG::2016-03-18 17:28:03,114::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/0
>MainThread::DEBUG::2016-03-18 17:28:03,115::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/1
>jsonrpc.Executor/0::DEBUG::2016-03-18 17:28:03,115::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:28:03,116::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/2
>jsonrpc.Executor/1::DEBUG::2016-03-18 17:28:03,116::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:28:03,117::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/3
>jsonrpc.Executor/2::DEBUG::2016-03-18 17:28:03,118::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:28:03,118::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/4
>jsonrpc.Executor/3::DEBUG::2016-03-18 17:28:03,119::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:28:03,119::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/5
>jsonrpc.Executor/4::DEBUG::2016-03-18 17:28:03,120::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:28:03,120::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/6
>jsonrpc.Executor/5::DEBUG::2016-03-18 17:28:03,121::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:28:03,121::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/7
>jsonrpc.Executor/6::DEBUG::2016-03-18 17:28:03,121::executor::171::Executor::(_run) Worker started
>jsonrpc.Executor/7::DEBUG::2016-03-18 17:28:03,122::executor::171::Executor::(_run) Worker started
>storageRefresh::DEBUG::2016-03-18 17:28:03,123::hba::62::Storage.HBA::(rescan) Scan finished
>storageRefresh::DEBUG::2016-03-18 17:28:03,124::misc::760::Storage.SamplingMethod::(__call__) Returning last result
>storageRefresh::DEBUG::2016-03-18 17:28:03,124::multipath::77::Storage.Misc.excCmd::(rescan) /usr/bin/taskset --cpu-list 0-1 /usr/bin/sudo -n /usr/sbin/multipath (cwd None)
>BindingXMLRPC::INFO::2016-03-18 17:28:03,143::bindingxmlrpc::62::vds::(threaded_start) XMLRPC server running
>MainThread::DEBUG::2016-03-18 17:28:03,151::executor::69::Executor::(start) Starting executor
>MainThread::DEBUG::2016-03-18 17:28:03,151::executor::157::Executor::(__init__) Starting worker periodic/0
>MainThread::DEBUG::2016-03-18 17:28:03,154::executor::157::Executor::(__init__) Starting worker periodic/1
>periodic/0::DEBUG::2016-03-18 17:28:03,155::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:28:03,155::executor::157::Executor::(__init__) Starting worker periodic/2
>periodic/1::DEBUG::2016-03-18 17:28:03,156::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:28:03,156::executor::157::Executor::(__init__) Starting worker periodic/3
>periodic/2::DEBUG::2016-03-18 17:28:03,156::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:28:03,157::libvirtconnection::161::root::(get) trying to connect libvirt
>periodic/3::DEBUG::2016-03-18 17:28:03,158::executor::171::Executor::(_run) Worker started
>clientIFinit::DEBUG::2016-03-18 17:28:03,180::clientIF::575::vds::(_recoverVm) Trying to recover ca440cf8-b140-46c1-8658-c2c71d0229cf
>MainThread::DEBUG::2016-03-18 17:28:03,206::periodic::153::virt.periodic.Operation::(start) starting operation <VmDispatcher operation=<class 'virt.periodic.UpdateVolumes'> at 0x24ad410>
>MainThread::DEBUG::2016-03-18 17:28:03,206::periodic::153::virt.periodic.Operation::(start) starting operation <VmDispatcher operation=<class 'virt.periodic.NumaInfoMonitor'> at 0x24ad650>
>MainThread::DEBUG::2016-03-18 17:28:03,207::periodic::153::virt.periodic.Operation::(start) starting operation <VmDispatcher operation=<class 'virt.periodic.BlockjobMonitor'> at 0x24ad6d0>
>MainThread::DEBUG::2016-03-18 17:28:03,207::periodic::153::virt.periodic.Operation::(start) starting operation <VMBulkSampler at 0x24ad750>
>MainThread::DEBUG::2016-03-18 17:28:03,207::periodic::153::virt.periodic.Operation::(start) starting operation <VmDispatcher operation=<class 'virt.periodic.DriveWatermarkMonitor'> at 0x2519c90>
>periodic/1::WARNING::2016-03-18 17:28:03,226::periodic::285::virt.vm::(__call__) vmId=`ca440cf8-b140-46c1-8658-c2c71d0229cf`::could not run on ca440cf8-b140-46c1-8658-c2c71d0229cf: domain not connected
>periodic/2::WARNING::2016-03-18 17:28:03,227::periodic::258::virt.periodic.VmDispatcher::(__call__) could not run <class 'virt.periodic.BlockjobMonitor'> on [u'ca440cf8-b140-46c1-8658-c2c71d0229cf']
>clientIFinit::INFO::2016-03-18 17:28:03,229::clientIF::479::vds::(_recoverExistingVms) recovery [1:1/1]: recovered domain ca440cf8-b140-46c1-8658-c2c71d0229cf from libvirt
>clientIFinit::INFO::2016-03-18 17:28:03,230::clientIF::521::vds::(_recoverExistingVms) recovery: waiting for 1 domains to go up
>MainThread::INFO::2016-03-18 17:28:18,622::vdsm::162::vds::(run) (PID: 21724) I am the actual vdsm 4.17.23.1-0.el7ev amd-4450b-4-1.englab.nay.redhat.com (3.10.0-363.el7.x86_64)
>MainThread::INFO::2016-03-18 17:28:18,623::vdsm::285::vds::(__set_cpu_affinity) VDSM will run with cpu affinity: frozenset([1])
>MainThread::DEBUG::2016-03-18 17:28:18,623::utils::671::root::(execCmd) /usr/bin/taskset --all-tasks --pid --cpu-list 1 21724 (cwd None)
>MainThread::DEBUG::2016-03-18 17:28:18,629::utils::689::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
>MainThread::DEBUG::2016-03-18 17:28:18,631::resourceManager::424::Storage.ResourceManager::(registerNamespace) Registering namespace 'Storage'
>MainThread::DEBUG::2016-03-18 17:28:18,631::threadPool::29::Storage.ThreadPool::(__init__) Enter - numThreads: 10, waitTimeout: 3, maxTasks: 500
>MainThread::DEBUG::2016-03-18 17:28:18,638::fileUtils::143::Storage.fileUtils::(createdir) Creating directory: /rhev/data-center/mnt mode: None
>MainThread::WARNING::2016-03-18 17:28:18,638::fileUtils::152::Storage.fileUtils::(createdir) Dir /rhev/data-center/mnt already exists
>MainThread::DEBUG::2016-03-18 17:28:18,645::sp::395::Storage.StoragePool::(cleanupMasterMount) master `/rhev/data-center/mnt/blockSD/c92de3f8-b279-489f-b69f-1b2e7bfdfccd/master` is not mounted, skipping
>MainThread::DEBUG::2016-03-18 17:28:18,690::hsm::409::Storage.Misc.excCmd::(__validateLvmLockingType) /usr/bin/taskset --cpu-list 0-1 /usr/bin/sudo -n /usr/sbin/lvm dumpconfig global/locking_type (cwd None)
>MainThread::DEBUG::2016-03-18 17:28:18,726::hsm::409::Storage.Misc.excCmd::(__validateLvmLockingType) SUCCESS: <err> = ''; <rc> = 0
>MainThread::DEBUG::2016-03-18 17:28:18,726::hsm::433::Storage.HSM::(__cleanStorageRepository) Started cleaning storage repository at '/rhev/data-center'
>MainThread::DEBUG::2016-03-18 17:28:18,730::hsm::465::Storage.HSM::(__cleanStorageRepository) White list: ['/rhev/data-center/hsm-tasks', '/rhev/data-center/hsm-tasks/*', '/rhev/data-center/mnt']
>MainThread::DEBUG::2016-03-18 17:28:18,730::hsm::466::Storage.HSM::(__cleanStorageRepository) Mount list: ['/rhev/data-center/mnt/10.73.194.27:_vol_S3_libvirtauto_yy_nfs1']
>MainThread::DEBUG::2016-03-18 17:28:18,730::hsm::468::Storage.HSM::(__cleanStorageRepository) Cleaning leftovers
>MainThread::DEBUG::2016-03-18 17:28:18,732::hsm::511::Storage.HSM::(__cleanStorageRepository) Finished cleaning storage repository at '/rhev/data-center'
>MainThread::INFO::2016-03-18 17:28:18,735::dispatcher::46::Storage.Dispatcher::(__init__) Starting StorageDispatcher...
>MainThread::DEBUG::2016-03-18 17:28:18,736::schedule::98::Scheduler::(start) Starting scheduler vdsm.Scheduler
>storageRefresh::DEBUG::2016-03-18 17:28:18,736::misc::750::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>storageRefresh::DEBUG::2016-03-18 17:28:18,736::misc::753::Storage.SamplingMethod::(__call__) Got in to sampling method
>storageRefresh::DEBUG::2016-03-18 17:28:18,736::misc::750::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>storageRefresh::DEBUG::2016-03-18 17:28:18,737::misc::753::Storage.SamplingMethod::(__call__) Got in to sampling method
>storageRefresh::DEBUG::2016-03-18 17:28:18,737::iscsi::434::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
>storageRefresh::DEBUG::2016-03-18 17:28:18,737::iscsiadm::97::Storage.Misc.excCmd::(_runCmd) /usr/bin/taskset --cpu-list 0-1 /usr/bin/sudo -n /sbin/iscsiadm -m session -R (cwd None)
>MainThread::DEBUG::2016-03-18 17:28:18,843::task::595::Storage.TaskManager.Task::(_updateState) Task=`61c4fa27-2726-42cf-9f5a-cd93ca3a0d94`::moving from state init -> state preparing
>MainThread::INFO::2016-03-18 17:28:18,843::logUtils::48::dispatcher::(wrapper) Run and protect: registerDomainStateChangeCallback(callbackFunc=<functools.partial object at 0x18d4050>)
>MainThread::INFO::2016-03-18 17:28:18,843::logUtils::51::dispatcher::(wrapper) Run and protect: registerDomainStateChangeCallback, Return response: None
>MainThread::DEBUG::2016-03-18 17:28:18,844::task::1191::Storage.TaskManager.Task::(prepare) Task=`61c4fa27-2726-42cf-9f5a-cd93ca3a0d94`::finished: None
>MainThread::DEBUG::2016-03-18 17:28:18,844::task::595::Storage.TaskManager.Task::(_updateState) Task=`61c4fa27-2726-42cf-9f5a-cd93ca3a0d94`::moving from state preparing -> state finished
>MainThread::DEBUG::2016-03-18 17:28:18,844::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>MainThread::DEBUG::2016-03-18 17:28:18,844::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>MainThread::DEBUG::2016-03-18 17:28:18,844::task::993::Storage.TaskManager.Task::(_decref) Task=`61c4fa27-2726-42cf-9f5a-cd93ca3a0d94`::ref 0 aborting False
>vdsm.Scheduler::DEBUG::2016-03-18 17:28:18,845::schedule::142::Scheduler::(_run) started
>storageRefresh::DEBUG::2016-03-18 17:28:18,846::misc::760::Storage.SamplingMethod::(__call__) Returning last result
>storageRefresh::DEBUG::2016-03-18 17:28:18,846::misc::750::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.hba.rescan)
>storageRefresh::DEBUG::2016-03-18 17:28:18,846::misc::753::Storage.SamplingMethod::(__call__) Got in to sampling method
>storageRefresh::DEBUG::2016-03-18 17:28:18,846::hba::56::Storage.HBA::(rescan) Starting scan
>storageRefresh::DEBUG::2016-03-18 17:28:18,847::supervdsm::76::SuperVdsmProxy::(_connect) Trying to connect to Super Vdsm
>MainThread::INFO::2016-03-18 17:28:18,849::momIF::46::MOM::(__init__) Preparing MOM interface
>MainThread::INFO::2016-03-18 17:28:18,851::momIF::55::MOM::(__init__) Using named unix socket /var/run/vdsm/mom-vdsm.sock
>MainThread::INFO::2016-03-18 17:28:18,852::secret::90::root::(clear) Unregistering all secrests
>MainThread::DEBUG::2016-03-18 17:28:18,852::libvirtconnection::161::root::(get) trying to connect libvirt
>MainThread::INFO::2016-03-18 17:28:18,882::vmchannels::211::vds::(settimeout) Setting channels' timeout to 30 seconds.
>clientIFinit::DEBUG::2016-03-18 17:28:18,883::clientIF::462::vds::(_recoverExistingVms) recovery: started
>MainThread::INFO::2016-03-18 17:28:18,886::protocoldetector::172::vds.MultiProtocolAcceptor::(__init__) Listening at 0.0.0.0:54321
>MainThread::DEBUG::2016-03-18 17:28:18,894::protocoldetector::199::vds.MultiProtocolAcceptor::(add_detector) Adding detector <rpc.bindingxmlrpc.XmlDetector instance at 0x198e9e0>
>VM Channels Listener::DEBUG::2016-03-18 17:28:19,015::vmchannels::193::vds::(run) Starting VM channels listener thread.
>MainThread::DEBUG::2016-03-18 17:28:19,016::protocoldetector::199::vds.MultiProtocolAcceptor::(add_detector) Adding detector <yajsonrpc.stompreactor.StompDetector instance at 0x1b2df80>
>MainThread::DEBUG::2016-03-18 17:28:19,016::executor::69::Executor::(start) Starting executor
>MainThread::DEBUG::2016-03-18 17:28:19,016::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/0
>MainThread::DEBUG::2016-03-18 17:28:19,017::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/1
>jsonrpc.Executor/0::DEBUG::2016-03-18 17:28:19,018::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:28:19,018::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/2
>jsonrpc.Executor/1::DEBUG::2016-03-18 17:28:19,019::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:28:19,019::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/3
>jsonrpc.Executor/2::DEBUG::2016-03-18 17:28:19,020::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:28:19,020::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/4
>jsonrpc.Executor/3::DEBUG::2016-03-18 17:28:19,021::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:28:19,021::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/5
>jsonrpc.Executor/4::DEBUG::2016-03-18 17:28:19,023::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:28:19,033::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/6
>jsonrpc.Executor/5::DEBUG::2016-03-18 17:28:19,034::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:28:19,034::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/7
>jsonrpc.Executor/6::DEBUG::2016-03-18 17:28:19,035::executor::171::Executor::(_run) Worker started
>jsonrpc.Executor/7::DEBUG::2016-03-18 17:28:19,035::executor::171::Executor::(_run) Worker started
>storageRefresh::DEBUG::2016-03-18 17:28:19,036::hba::62::Storage.HBA::(rescan) Scan finished
>storageRefresh::DEBUG::2016-03-18 17:28:19,037::misc::760::Storage.SamplingMethod::(__call__) Returning last result
>storageRefresh::DEBUG::2016-03-18 17:28:19,037::multipath::77::Storage.Misc.excCmd::(rescan) /usr/bin/taskset --cpu-list 0-1 /usr/bin/sudo -n /usr/sbin/multipath (cwd None)
>clientIFinit::DEBUG::2016-03-18 17:28:19,060::clientIF::575::vds::(_recoverVm) Trying to recover ca440cf8-b140-46c1-8658-c2c71d0229cf
>BindingXMLRPC::INFO::2016-03-18 17:28:19,036::bindingxmlrpc::62::vds::(threaded_start) XMLRPC server running
>MainThread::DEBUG::2016-03-18 17:28:19,063::executor::69::Executor::(start) Starting executor
>MainThread::DEBUG::2016-03-18 17:28:19,063::executor::157::Executor::(__init__) Starting worker periodic/0
>MainThread::DEBUG::2016-03-18 17:28:19,065::executor::157::Executor::(__init__) Starting worker periodic/1
>clientIFinit::DEBUG::2016-03-18 17:28:19,068::libvirtconnection::161::root::(get) trying to connect libvirt
>periodic/0::DEBUG::2016-03-18 17:28:19,068::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:28:19,069::executor::157::Executor::(__init__) Starting worker periodic/2
>periodic/1::DEBUG::2016-03-18 17:28:19,069::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:28:19,070::executor::157::Executor::(__init__) Starting worker periodic/3
>periodic/2::DEBUG::2016-03-18 17:28:19,070::executor::171::Executor::(_run) Worker started
>periodic/3::DEBUG::2016-03-18 17:28:19,071::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:28:19,124::periodic::153::virt.periodic.Operation::(start) starting operation <VmDispatcher operation=<class 'virt.periodic.UpdateVolumes'> at 0x1be1c10>
>MainThread::DEBUG::2016-03-18 17:28:19,125::periodic::153::virt.periodic.Operation::(start) starting operation <VmDispatcher operation=<class 'virt.periodic.NumaInfoMonitor'> at 0x1be1e50>
>MainThread::DEBUG::2016-03-18 17:28:19,125::periodic::153::virt.periodic.Operation::(start) starting operation <VmDispatcher operation=<class 'virt.periodic.BlockjobMonitor'> at 0x1be1ed0>
>MainThread::DEBUG::2016-03-18 17:28:19,125::periodic::153::virt.periodic.Operation::(start) starting operation <VMBulkSampler at 0x1be1f50>
>MainThread::DEBUG::2016-03-18 17:28:19,125::periodic::153::virt.periodic.Operation::(start) starting operation <VmDispatcher operation=<class 'virt.periodic.DriveWatermarkMonitor'> at 0x1c01610>
>periodic/0::WARNING::2016-03-18 17:28:19,126::periodic::258::virt.periodic.VmDispatcher::(__call__) could not run <class 'virt.periodic.BlockjobMonitor'> on [u'ca440cf8-b140-46c1-8658-c2c71d0229cf']
>periodic/1::WARNING::2016-03-18 17:28:19,127::periodic::285::virt.vm::(__call__) vmId=`ca440cf8-b140-46c1-8658-c2c71d0229cf`::could not run on ca440cf8-b140-46c1-8658-c2c71d0229cf: domain not connected
>clientIFinit::INFO::2016-03-18 17:28:19,128::clientIF::479::vds::(_recoverExistingVms) recovery [1:1/1]: recovered domain ca440cf8-b140-46c1-8658-c2c71d0229cf from libvirt
>clientIFinit::INFO::2016-03-18 17:28:19,129::clientIF::521::vds::(_recoverExistingVms) recovery: waiting for 1 domains to go up
>Thread-13::DEBUG::2016-03-18 17:28:19,129::vm::697::virt.vm::(_startUnderlyingVm) vmId=`ca440cf8-b140-46c1-8658-c2c71d0229cf`::Start
>Thread-13::INFO::2016-03-18 17:28:19,130::vm::1850::virt.vm::(_run) vmId=`ca440cf8-b140-46c1-8658-c2c71d0229cf`::VM wrapper has started
>Thread-13::DEBUG::2016-03-18 17:28:19,131::task::595::Storage.TaskManager.Task::(_updateState) Task=`94c94daa-d501-4be2-a81b-a81ae664367f`::moving from state init -> state preparing
>Thread-13::INFO::2016-03-18 17:28:19,131::logUtils::48::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID=u'c1d2e073-fa2e-47a9-8a0c-3ceefad91685', spUUID=u'acc8b348-81f6-4bf2-9ffe-f1da755bb38d', imgUUID=u'e7e0392e-bcb9-4486-9e41-e163296528f5', volUUID=u'81610d39-bca1-4c94-b193-fae83a8a1912', options=None)
>Thread-13::DEBUG::2016-03-18 17:28:19,132::misc::750::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>MainThread::INFO::2016-03-18 17:28:33,642::vdsm::162::vds::(run) (PID: 21905) I am the actual vdsm 4.17.23.1-0.el7ev amd-4450b-4-1.englab.nay.redhat.com (3.10.0-363.el7.x86_64)
>MainThread::INFO::2016-03-18 17:28:33,643::vdsm::285::vds::(__set_cpu_affinity) VDSM will run with cpu affinity: frozenset([1])
>MainThread::DEBUG::2016-03-18 17:28:33,643::utils::671::root::(execCmd) /usr/bin/taskset --all-tasks --pid --cpu-list 1 21905 (cwd None)
>MainThread::DEBUG::2016-03-18 17:28:33,649::utils::689::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
>MainThread::DEBUG::2016-03-18 17:28:33,650::resourceManager::424::Storage.ResourceManager::(registerNamespace) Registering namespace 'Storage'
>MainThread::DEBUG::2016-03-18 17:28:33,651::threadPool::29::Storage.ThreadPool::(__init__) Enter - numThreads: 10, waitTimeout: 3, maxTasks: 500
>MainThread::DEBUG::2016-03-18 17:28:33,655::fileUtils::143::Storage.fileUtils::(createdir) Creating directory: /rhev/data-center/mnt mode: None
>MainThread::WARNING::2016-03-18 17:28:33,656::fileUtils::152::Storage.fileUtils::(createdir) Dir /rhev/data-center/mnt already exists
>MainThread::DEBUG::2016-03-18 17:28:33,661::sp::395::Storage.StoragePool::(cleanupMasterMount) master `/rhev/data-center/mnt/blockSD/c92de3f8-b279-489f-b69f-1b2e7bfdfccd/master` is not mounted, skipping
>MainThread::DEBUG::2016-03-18 17:28:33,704::hsm::409::Storage.Misc.excCmd::(__validateLvmLockingType) /usr/bin/taskset --cpu-list 0-1 /usr/bin/sudo -n /usr/sbin/lvm dumpconfig global/locking_type (cwd None)
>MainThread::DEBUG::2016-03-18 17:28:33,737::hsm::409::Storage.Misc.excCmd::(__validateLvmLockingType) SUCCESS: <err> = ''; <rc> = 0
>MainThread::DEBUG::2016-03-18 17:28:33,737::hsm::433::Storage.HSM::(__cleanStorageRepository) Started cleaning storage repository at '/rhev/data-center'
>MainThread::DEBUG::2016-03-18 17:28:33,741::hsm::465::Storage.HSM::(__cleanStorageRepository) White list: ['/rhev/data-center/hsm-tasks', '/rhev/data-center/hsm-tasks/*', '/rhev/data-center/mnt']
>MainThread::DEBUG::2016-03-18 17:28:33,741::hsm::466::Storage.HSM::(__cleanStorageRepository) Mount list: ['/rhev/data-center/mnt/10.73.194.27:_vol_S3_libvirtauto_yy_nfs1']
>MainThread::DEBUG::2016-03-18 17:28:33,741::hsm::468::Storage.HSM::(__cleanStorageRepository) Cleaning leftovers
>MainThread::DEBUG::2016-03-18 17:28:33,743::hsm::511::Storage.HSM::(__cleanStorageRepository) Finished cleaning storage repository at '/rhev/data-center'
>MainThread::INFO::2016-03-18 17:28:33,746::dispatcher::46::Storage.Dispatcher::(__init__) Starting StorageDispatcher...
>MainThread::DEBUG::2016-03-18 17:28:33,747::schedule::98::Scheduler::(start) Starting scheduler vdsm.Scheduler
>storageRefresh::DEBUG::2016-03-18 17:28:33,747::misc::750::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>storageRefresh::DEBUG::2016-03-18 17:28:33,747::misc::753::Storage.SamplingMethod::(__call__) Got in to sampling method
>storageRefresh::DEBUG::2016-03-18 17:28:33,747::misc::750::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>storageRefresh::DEBUG::2016-03-18 17:28:33,748::misc::753::Storage.SamplingMethod::(__call__) Got in to sampling method
>storageRefresh::DEBUG::2016-03-18 17:28:33,748::iscsi::434::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
>storageRefresh::DEBUG::2016-03-18 17:28:33,748::iscsiadm::97::Storage.Misc.excCmd::(_runCmd) /usr/bin/taskset --cpu-list 0-1 /usr/bin/sudo -n /sbin/iscsiadm -m session -R (cwd None)
>MainThread::DEBUG::2016-03-18 17:28:33,851::task::595::Storage.TaskManager.Task::(_updateState) Task=`e957e73e-b2c5-4308-a195-cd7367676fd4`::moving from state init -> state preparing
>MainThread::INFO::2016-03-18 17:28:33,852::logUtils::48::dispatcher::(wrapper) Run and protect: registerDomainStateChangeCallback(callbackFunc=<functools.partial object at 0x26d1050>)
>MainThread::INFO::2016-03-18 17:28:33,852::logUtils::51::dispatcher::(wrapper) Run and protect: registerDomainStateChangeCallback, Return response: None
>MainThread::DEBUG::2016-03-18 17:28:33,852::task::1191::Storage.TaskManager.Task::(prepare) Task=`e957e73e-b2c5-4308-a195-cd7367676fd4`::finished: None
>MainThread::DEBUG::2016-03-18 17:28:33,852::task::595::Storage.TaskManager.Task::(_updateState) Task=`e957e73e-b2c5-4308-a195-cd7367676fd4`::moving from state preparing -> state finished
>MainThread::DEBUG::2016-03-18 17:28:33,852::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>MainThread::DEBUG::2016-03-18 17:28:33,853::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>MainThread::DEBUG::2016-03-18 17:28:33,853::task::993::Storage.TaskManager.Task::(_decref) Task=`e957e73e-b2c5-4308-a195-cd7367676fd4`::ref 0 aborting False
>vdsm.Scheduler::DEBUG::2016-03-18 17:28:33,855::schedule::142::Scheduler::(_run) started
>storageRefresh::DEBUG::2016-03-18 17:28:33,855::misc::760::Storage.SamplingMethod::(__call__) Returning last result
>storageRefresh::DEBUG::2016-03-18 17:28:33,856::misc::750::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.hba.rescan)
>storageRefresh::DEBUG::2016-03-18 17:28:33,856::misc::753::Storage.SamplingMethod::(__call__) Got in to sampling method
>storageRefresh::DEBUG::2016-03-18 17:28:33,856::hba::56::Storage.HBA::(rescan) Starting scan
>storageRefresh::DEBUG::2016-03-18 17:28:33,856::supervdsm::76::SuperVdsmProxy::(_connect) Trying to connect to Super Vdsm
>MainThread::INFO::2016-03-18 17:28:33,858::momIF::46::MOM::(__init__) Preparing MOM interface
>MainThread::INFO::2016-03-18 17:28:33,860::momIF::55::MOM::(__init__) Using named unix socket /var/run/vdsm/mom-vdsm.sock
>MainThread::INFO::2016-03-18 17:28:33,861::secret::90::root::(clear) Unregistering all secrests
>MainThread::DEBUG::2016-03-18 17:28:33,861::libvirtconnection::161::root::(get) trying to connect libvirt
>MainThread::INFO::2016-03-18 17:28:33,886::vmchannels::211::vds::(settimeout) Setting channels' timeout to 30 seconds.
>clientIFinit::DEBUG::2016-03-18 17:28:33,887::clientIF::462::vds::(_recoverExistingVms) recovery: started
>MainThread::INFO::2016-03-18 17:28:33,890::protocoldetector::172::vds.MultiProtocolAcceptor::(__init__) Listening at 0.0.0.0:54321
>MainThread::DEBUG::2016-03-18 17:28:33,899::protocoldetector::199::vds.MultiProtocolAcceptor::(add_detector) Adding detector <rpc.bindingxmlrpc.XmlDetector instance at 0x278a9e0>
>VM Channels Listener::DEBUG::2016-03-18 17:28:34,011::vmchannels::193::vds::(run) Starting VM channels listener thread.
>MainThread::DEBUG::2016-03-18 17:28:34,012::protocoldetector::199::vds.MultiProtocolAcceptor::(add_detector) Adding detector <yajsonrpc.stompreactor.StompDetector instance at 0x2922cb0>
>MainThread::DEBUG::2016-03-18 17:28:34,012::executor::69::Executor::(start) Starting executor
>MainThread::DEBUG::2016-03-18 17:28:34,012::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/0
>MainThread::DEBUG::2016-03-18 17:28:34,013::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/1
>jsonrpc.Executor/0::DEBUG::2016-03-18 17:28:34,013::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:28:34,014::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/2
>jsonrpc.Executor/1::DEBUG::2016-03-18 17:28:34,015::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:28:34,016::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/3
>jsonrpc.Executor/2::DEBUG::2016-03-18 17:28:34,016::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:28:34,017::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/4
>jsonrpc.Executor/3::DEBUG::2016-03-18 17:28:34,017::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:28:34,024::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/5
>jsonrpc.Executor/4::DEBUG::2016-03-18 17:28:34,025::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:28:34,025::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/6
>jsonrpc.Executor/5::DEBUG::2016-03-18 17:28:34,026::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:28:34,026::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/7
>jsonrpc.Executor/6::DEBUG::2016-03-18 17:28:34,027::executor::171::Executor::(_run) Worker started
>jsonrpc.Executor/7::DEBUG::2016-03-18 17:28:34,028::executor::171::Executor::(_run) Worker started
>BindingXMLRPC::INFO::2016-03-18 17:28:34,029::bindingxmlrpc::62::vds::(threaded_start) XMLRPC server running
>storageRefresh::DEBUG::2016-03-18 17:28:34,036::hba::62::Storage.HBA::(rescan) Scan finished
>storageRefresh::DEBUG::2016-03-18 17:28:34,037::misc::760::Storage.SamplingMethod::(__call__) Returning last result
>storageRefresh::DEBUG::2016-03-18 17:28:34,037::multipath::77::Storage.Misc.excCmd::(rescan) /usr/bin/taskset --cpu-list 0-1 /usr/bin/sudo -n /usr/sbin/multipath (cwd None)
>MainThread::DEBUG::2016-03-18 17:28:34,051::executor::69::Executor::(start) Starting executor
>MainThread::DEBUG::2016-03-18 17:28:34,051::executor::157::Executor::(__init__) Starting worker periodic/0
>MainThread::DEBUG::2016-03-18 17:28:34,054::executor::157::Executor::(__init__) Starting worker periodic/1
>periodic/0::DEBUG::2016-03-18 17:28:34,054::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:28:34,055::executor::157::Executor::(__init__) Starting worker periodic/2
>periodic/1::DEBUG::2016-03-18 17:28:34,055::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:28:34,056::executor::157::Executor::(__init__) Starting worker periodic/3
>periodic/2::DEBUG::2016-03-18 17:28:34,056::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:28:34,057::libvirtconnection::161::root::(get) trying to connect libvirt
>periodic/3::DEBUG::2016-03-18 17:28:34,058::executor::171::Executor::(_run) Worker started
>clientIFinit::DEBUG::2016-03-18 17:28:34,084::clientIF::575::vds::(_recoverVm) Trying to recover ca440cf8-b140-46c1-8658-c2c71d0229cf
>MainThread::DEBUG::2016-03-18 17:28:34,102::periodic::153::virt.periodic.Operation::(start) starting operation <VmDispatcher operation=<class 'virt.periodic.UpdateVolumes'> at 0x2944410>
>MainThread::DEBUG::2016-03-18 17:28:34,102::periodic::153::virt.periodic.Operation::(start) starting operation <VmDispatcher operation=<class 'virt.periodic.NumaInfoMonitor'> at 0x2944650>
>MainThread::DEBUG::2016-03-18 17:28:34,103::periodic::153::virt.periodic.Operation::(start) starting operation <VmDispatcher operation=<class 'virt.periodic.BlockjobMonitor'> at 0x29446d0>
>MainThread::DEBUG::2016-03-18 17:28:34,103::periodic::153::virt.periodic.Operation::(start) starting operation <VMBulkSampler at 0x2944750>
>MainThread::DEBUG::2016-03-18 17:28:34,103::periodic::153::virt.periodic.Operation::(start) starting operation <VmDispatcher operation=<class 'virt.periodic.DriveWatermarkMonitor'> at 0x29b1c90>
>periodic/1::WARNING::2016-03-18 17:28:34,121::periodic::285::virt.vm::(__call__) vmId=`ca440cf8-b140-46c1-8658-c2c71d0229cf`::could not run on ca440cf8-b140-46c1-8658-c2c71d0229cf: domain not connected
>periodic/2::WARNING::2016-03-18 17:28:34,122::periodic::258::virt.periodic.VmDispatcher::(__call__) could not run <class 'virt.periodic.BlockjobMonitor'> on [u'ca440cf8-b140-46c1-8658-c2c71d0229cf']
>clientIFinit::INFO::2016-03-18 17:28:34,125::clientIF::479::vds::(_recoverExistingVms) recovery [1:1/1]: recovered domain ca440cf8-b140-46c1-8658-c2c71d0229cf from libvirt
>clientIFinit::INFO::2016-03-18 17:28:34,125::clientIF::521::vds::(_recoverExistingVms) recovery: waiting for 1 domains to go up
>Thread-13::DEBUG::2016-03-18 17:28:34,126::vm::697::virt.vm::(_startUnderlyingVm) vmId=`ca440cf8-b140-46c1-8658-c2c71d0229cf`::Start
>Thread-13::INFO::2016-03-18 17:28:34,126::vm::1850::virt.vm::(_run) vmId=`ca440cf8-b140-46c1-8658-c2c71d0229cf`::VM wrapper has started
>Thread-13::DEBUG::2016-03-18 17:28:34,127::task::595::Storage.TaskManager.Task::(_updateState) Task=`bbae844a-7e48-4407-a294-bdea002067c1`::moving from state init -> state preparing
>Thread-13::INFO::2016-03-18 17:28:34,128::logUtils::48::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID=u'c1d2e073-fa2e-47a9-8a0c-3ceefad91685', spUUID=u'acc8b348-81f6-4bf2-9ffe-f1da755bb38d', imgUUID=u'e7e0392e-bcb9-4486-9e41-e163296528f5', volUUID=u'81610d39-bca1-4c94-b193-fae83a8a1912', options=None)
>Thread-13::DEBUG::2016-03-18 17:28:34,128::misc::750::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>storageRefresh::DEBUG::2016-03-18 17:28:34,141::multipath::77::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
>storageRefresh::DEBUG::2016-03-18 17:28:34,142::utils::671::root::(execCmd) /usr/bin/taskset --cpu-list 0-1 /sbin/udevadm settle --timeout=5 (cwd None)
>MainThread::INFO::2016-03-18 17:28:48,668::vdsm::162::vds::(run) (PID: 22090) I am the actual vdsm 4.17.23.1-0.el7ev amd-4450b-4-1.englab.nay.redhat.com (3.10.0-363.el7.x86_64)
>MainThread::INFO::2016-03-18 17:28:48,669::vdsm::285::vds::(__set_cpu_affinity) VDSM will run with cpu affinity: frozenset([1])
>MainThread::DEBUG::2016-03-18 17:28:48,669::utils::671::root::(execCmd) /usr/bin/taskset --all-tasks --pid --cpu-list 1 22090 (cwd None)
>MainThread::DEBUG::2016-03-18 17:28:48,675::utils::689::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
>MainThread::DEBUG::2016-03-18 17:28:48,677::resourceManager::424::Storage.ResourceManager::(registerNamespace) Registering namespace 'Storage'
>MainThread::DEBUG::2016-03-18 17:28:48,677::threadPool::29::Storage.ThreadPool::(__init__) Enter - numThreads: 10, waitTimeout: 3, maxTasks: 500
>MainThread::DEBUG::2016-03-18 17:28:48,682::fileUtils::143::Storage.fileUtils::(createdir) Creating directory: /rhev/data-center/mnt mode: None
>MainThread::WARNING::2016-03-18 17:28:48,682::fileUtils::152::Storage.fileUtils::(createdir) Dir /rhev/data-center/mnt already exists
>MainThread::DEBUG::2016-03-18 17:28:48,688::sp::395::Storage.StoragePool::(cleanupMasterMount) master `/rhev/data-center/mnt/blockSD/c92de3f8-b279-489f-b69f-1b2e7bfdfccd/master` is not mounted, skipping
>MainThread::DEBUG::2016-03-18 17:28:48,733::hsm::409::Storage.Misc.excCmd::(__validateLvmLockingType) /usr/bin/taskset --cpu-list 0-1 /usr/bin/sudo -n /usr/sbin/lvm dumpconfig global/locking_type (cwd None)
>MainThread::DEBUG::2016-03-18 17:28:48,766::hsm::409::Storage.Misc.excCmd::(__validateLvmLockingType) SUCCESS: <err> = ''; <rc> = 0
>MainThread::DEBUG::2016-03-18 17:28:48,766::hsm::433::Storage.HSM::(__cleanStorageRepository) Started cleaning storage repository at '/rhev/data-center'
>MainThread::DEBUG::2016-03-18 17:28:48,770::hsm::465::Storage.HSM::(__cleanStorageRepository) White list: ['/rhev/data-center/hsm-tasks', '/rhev/data-center/hsm-tasks/*', '/rhev/data-center/mnt']
>MainThread::DEBUG::2016-03-18 17:28:48,770::hsm::466::Storage.HSM::(__cleanStorageRepository) Mount list: ['/rhev/data-center/mnt/10.73.194.27:_vol_S3_libvirtauto_yy_nfs1']
>MainThread::DEBUG::2016-03-18 17:28:48,770::hsm::468::Storage.HSM::(__cleanStorageRepository) Cleaning leftovers
>MainThread::DEBUG::2016-03-18 17:28:48,772::hsm::511::Storage.HSM::(__cleanStorageRepository) Finished cleaning storage repository at '/rhev/data-center'
>MainThread::INFO::2016-03-18 17:28:48,775::dispatcher::46::Storage.Dispatcher::(__init__) Starting StorageDispatcher...
>MainThread::DEBUG::2016-03-18 17:28:48,775::schedule::98::Scheduler::(start) Starting scheduler vdsm.Scheduler
>storageRefresh::DEBUG::2016-03-18 17:28:48,776::misc::750::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>storageRefresh::DEBUG::2016-03-18 17:28:48,776::misc::753::Storage.SamplingMethod::(__call__) Got in to sampling method
>storageRefresh::DEBUG::2016-03-18 17:28:48,776::misc::750::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>storageRefresh::DEBUG::2016-03-18 17:28:48,776::misc::753::Storage.SamplingMethod::(__call__) Got in to sampling method
>storageRefresh::DEBUG::2016-03-18 17:28:48,777::iscsi::434::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
>storageRefresh::DEBUG::2016-03-18 17:28:48,777::iscsiadm::97::Storage.Misc.excCmd::(_runCmd) /usr/bin/taskset --cpu-list 0-1 /usr/bin/sudo -n /sbin/iscsiadm -m session -R (cwd None)
>MainThread::DEBUG::2016-03-18 17:28:48,880::task::595::Storage.TaskManager.Task::(_updateState) Task=`50fa6a97-0b15-4c37-99a2-6d61437a3468`::moving from state init -> state preparing
>MainThread::INFO::2016-03-18 17:28:48,881::logUtils::48::dispatcher::(wrapper) Run and protect: registerDomainStateChangeCallback(callbackFunc=<functools.partial object at 0x1f21050>)
>MainThread::INFO::2016-03-18 17:28:48,881::logUtils::51::dispatcher::(wrapper) Run and protect: registerDomainStateChangeCallback, Return response: None
>MainThread::DEBUG::2016-03-18 17:28:48,881::task::1191::Storage.TaskManager.Task::(prepare) Task=`50fa6a97-0b15-4c37-99a2-6d61437a3468`::finished: None
>MainThread::DEBUG::2016-03-18 17:28:48,881::task::595::Storage.TaskManager.Task::(_updateState) Task=`50fa6a97-0b15-4c37-99a2-6d61437a3468`::moving from state preparing -> state finished
>MainThread::DEBUG::2016-03-18 17:28:48,881::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>MainThread::DEBUG::2016-03-18 17:28:48,882::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>MainThread::DEBUG::2016-03-18 17:28:48,882::task::993::Storage.TaskManager.Task::(_decref) Task=`50fa6a97-0b15-4c37-99a2-6d61437a3468`::ref 0 aborting False
>vdsm.Scheduler::DEBUG::2016-03-18 17:28:48,884::schedule::142::Scheduler::(_run) started
>storageRefresh::DEBUG::2016-03-18 17:28:48,884::misc::760::Storage.SamplingMethod::(__call__) Returning last result
>storageRefresh::DEBUG::2016-03-18 17:28:48,885::misc::750::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.hba.rescan)
>storageRefresh::DEBUG::2016-03-18 17:28:48,885::misc::753::Storage.SamplingMethod::(__call__) Got in to sampling method
>storageRefresh::DEBUG::2016-03-18 17:28:48,885::hba::56::Storage.HBA::(rescan) Starting scan
>storageRefresh::DEBUG::2016-03-18 17:28:48,885::supervdsm::76::SuperVdsmProxy::(_connect) Trying to connect to Super Vdsm
>MainThread::INFO::2016-03-18 17:28:48,887::momIF::46::MOM::(__init__) Preparing MOM interface
>MainThread::INFO::2016-03-18 17:28:48,890::momIF::55::MOM::(__init__) Using named unix socket /var/run/vdsm/mom-vdsm.sock
>MainThread::INFO::2016-03-18 17:28:48,891::secret::90::root::(clear) Unregistering all secrests
>MainThread::DEBUG::2016-03-18 17:28:48,891::libvirtconnection::161::root::(get) trying to connect libvirt
>MainThread::INFO::2016-03-18 17:28:48,915::vmchannels::211::vds::(settimeout) Setting channels' timeout to 30 seconds.
>clientIFinit::DEBUG::2016-03-18 17:28:48,916::clientIF::462::vds::(_recoverExistingVms) recovery: started
>MainThread::INFO::2016-03-18 17:28:48,919::protocoldetector::172::vds.MultiProtocolAcceptor::(__init__) Listening at 0.0.0.0:54321
>MainThread::DEBUG::2016-03-18 17:28:48,928::protocoldetector::199::vds.MultiProtocolAcceptor::(add_detector) Adding detector <rpc.bindingxmlrpc.XmlDetector instance at 0x1fda9e0>
>VM Channels Listener::DEBUG::2016-03-18 17:28:49,041::vmchannels::193::vds::(run) Starting VM channels listener thread.
>MainThread::DEBUG::2016-03-18 17:28:49,042::protocoldetector::199::vds.MultiProtocolAcceptor::(add_detector) Adding detector <yajsonrpc.stompreactor.StompDetector instance at 0x2172cb0>
>MainThread::DEBUG::2016-03-18 17:28:49,042::executor::69::Executor::(start) Starting executor
>MainThread::DEBUG::2016-03-18 17:28:49,042::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/0
>MainThread::DEBUG::2016-03-18 17:28:49,043::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/1
>jsonrpc.Executor/0::DEBUG::2016-03-18 17:28:49,044::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:28:49,044::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/2
>jsonrpc.Executor/1::DEBUG::2016-03-18 17:28:49,046::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:28:49,047::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/3
>jsonrpc.Executor/2::DEBUG::2016-03-18 17:28:49,048::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:28:49,048::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/4
>jsonrpc.Executor/3::DEBUG::2016-03-18 17:28:49,049::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:28:49,049::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/5
>jsonrpc.Executor/4::DEBUG::2016-03-18 17:28:49,050::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:28:49,050::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/6
>jsonrpc.Executor/5::DEBUG::2016-03-18 17:28:49,051::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:28:49,051::executor::157::Executor::(__init__) Starting worker jsonrpc.Executor/7
>jsonrpc.Executor/6::DEBUG::2016-03-18 17:28:49,051::executor::171::Executor::(_run) Worker started
>jsonrpc.Executor/7::DEBUG::2016-03-18 17:28:49,053::executor::171::Executor::(_run) Worker started
>BindingXMLRPC::INFO::2016-03-18 17:28:49,053::bindingxmlrpc::62::vds::(threaded_start) XMLRPC server running
>storageRefresh::DEBUG::2016-03-18 17:28:49,062::hba::62::Storage.HBA::(rescan) Scan finished
>storageRefresh::DEBUG::2016-03-18 17:28:49,063::misc::760::Storage.SamplingMethod::(__call__) Returning last result
>storageRefresh::DEBUG::2016-03-18 17:28:49,063::multipath::77::Storage.Misc.excCmd::(rescan) /usr/bin/taskset --cpu-list 0-1 /usr/bin/sudo -n /usr/sbin/multipath (cwd None)
>MainThread::DEBUG::2016-03-18 17:28:49,080::executor::69::Executor::(start) Starting executor
>MainThread::DEBUG::2016-03-18 17:28:49,081::executor::157::Executor::(__init__) Starting worker periodic/0
>MainThread::DEBUG::2016-03-18 17:28:49,083::executor::157::Executor::(__init__) Starting worker periodic/1
>periodic/0::DEBUG::2016-03-18 17:28:49,084::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:28:49,084::executor::157::Executor::(__init__) Starting worker periodic/2
>periodic/1::DEBUG::2016-03-18 17:28:49,085::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:28:49,085::executor::157::Executor::(__init__) Starting worker periodic/3
>periodic/2::DEBUG::2016-03-18 17:28:49,086::executor::171::Executor::(_run) Worker started
>MainThread::DEBUG::2016-03-18 17:28:49,086::libvirtconnection::161::root::(get) trying to connect libvirt
>periodic/3::DEBUG::2016-03-18 17:28:49,087::executor::171::Executor::(_run) Worker started
>clientIFinit::DEBUG::2016-03-18 17:28:49,114::clientIF::575::vds::(_recoverVm) Trying to recover ca440cf8-b140-46c1-8658-c2c71d0229cf
>MainThread::DEBUG::2016-03-18 17:28:49,130::periodic::153::virt.periodic.Operation::(start) starting operation <VmDispatcher operation=<class 'virt.periodic.UpdateVolumes'> at 0x218f710>
>MainThread::DEBUG::2016-03-18 17:28:49,131::periodic::153::virt.periodic.Operation::(start) starting operation <VmDispatcher operation=<class 'virt.periodic.NumaInfoMonitor'> at 0x218f210>
>MainThread::DEBUG::2016-03-18 17:28:49,131::periodic::153::virt.periodic.Operation::(start) starting operation <VmDispatcher operation=<class 'virt.periodic.BlockjobMonitor'> at 0x218f290>
>MainThread::DEBUG::2016-03-18 17:28:49,131::periodic::153::virt.periodic.Operation::(start) starting operation <VMBulkSampler at 0x218f310>
>MainThread::DEBUG::2016-03-18 17:28:49,131::periodic::153::virt.periodic.Operation::(start) starting operation <VmDispatcher operation=<class 'virt.periodic.DriveWatermarkMonitor'> at 0x2201c90>
>periodic/1::WARNING::2016-03-18 17:28:49,149::periodic::285::virt.vm::(__call__) vmId=`ca440cf8-b140-46c1-8658-c2c71d0229cf`::could not run on ca440cf8-b140-46c1-8658-c2c71d0229cf: domain not connected
>periodic/2::WARNING::2016-03-18 17:28:49,149::periodic::258::virt.periodic.VmDispatcher::(__call__) could not run <class 'virt.periodic.BlockjobMonitor'> on [u'ca440cf8-b140-46c1-8658-c2c71d0229cf']

Actions: View

Attachments on bug 1318902: 1137728 | 1137729 | 1138406 | 1138407 | 1138408 | 1148073 | 1148074 | 1148075