Login
Log in using an SSO provider:
Fedora Account System
Red Hat Associate
Red Hat Customer
Login using a Red Hat Bugzilla account
Forgot Password
Create an Account
Red Hat Bugzilla – Attachment 1137728 Details for
Bug 1318902
Cannot start guest on RHEL 7.3 host via RHEVM
Home
New
Search
Simple Search
Advanced Search
My Links
Browse
Requests
Reports
Current State
Search
Tabular reports
Graphical reports
Duplicates
Other Reports
User Changes
Plotly Reports
Bug Status
Bug Severity
Non-Defaults
Product Dashboard
Help
Page Help!
Bug Writing Guidelines
What's new
Browser Support Policy
5.0.4.rh92 Release notes
FAQ
Guides index
User guide
Web Services
Contact
Legal
[?]
This site requires JavaScript to be enabled to function correctly, please enable it.
vdsm log
vdsm.log (text/plain), 218.27 KB, created by
Yang Yang
on 2016-03-18 09:29:48 UTC
(
hide
)
Description:
vdsm log
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']
You cannot view the attachment while viewing its details because your browser does not support IFRAMEs.
View the attachment on a separate page
.
View Attachment As Raw
Actions:
View
Attachments on
bug 1318902
: 1137728 |
1137729
|
1138406
|
1138407
|
1138408
|
1148073
|
1148074
|
1148075