Attachment 627512 Details for Bug 837003 – VDSM log

VDSM log

vdsm.log (text/plain), 136.49 KB, created by Pavel Novotny on 2012-10-15 15:19:32 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Pavel Novotny

Created: 2012-10-15 15:19:32 UTC

Size: 136.49 KB

patch

obsolete

>Thread-676::DEBUG::2012-10-15 14:14:58,252::BindingXMLRPC::171::vds::(wrapper) [10.35.70.46]
>Thread-676::DEBUG::2012-10-15 14:14:58,252::task::588::TaskManager.Task::(_updateState) Task=`bd2eaec3-7f7e-40fc-be49-c605f6507119`::moving from state init -> state preparing
>Thread-676::INFO::2012-10-15 14:14:58,253::logUtils::37::dispatcher::(wrapper) Run and protect: createVolume(sdUUID='3774dc69-8ba3-456e-b584-4c08e3ba3826', spUUID='e42f70cc-802e-46be-b931-867450cc6282', imgUUID='ffc59ea3-64f7-4fbf-ae9a-889a6efbf331', size='1149239296', volFormat=5, preallocate=2, diskType=2, volUUID='f6ee3a1c-e0e3-470c-a175-63c17eafb0bd', desc='', srcImgUUID='00000000-0000-0000-0000-000000000000', srcVolUUID='00000000-0000-0000-0000-000000000000')
>Thread-676::INFO::2012-10-15 14:14:58,253::fileSD::227::Storage.StorageDomain::(validate) sdUUID=3774dc69-8ba3-456e-b584-4c08e3ba3826
>Thread-676::DEBUG::2012-10-15 14:14:58,257::persistentDict::226::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=DataDomain01', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=DataCenter01', 'POOL_DOMAINS=602b2bde-9a66-4fc3-91ef-8a85894c087c:Attached,3774dc69-8ba3-456e-b584-4c08e3ba3826:Active', 'POOL_SPM_ID=1', 'POOL_SPM_LVER=0', 'POOL_UUID=e42f70cc-802e-46be-b931-867450cc6282', 'REMOTE_PATH=tiger.qa.lab.tlv.redhat.com:/export/storage_l2Xi_4_nfs_20121015144737844796', 'ROLE=Master', 'SDUUID=3774dc69-8ba3-456e-b584-4c08e3ba3826', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=9dc2700e4368e38013a83258e3ccf7d3ab2f6288']
>Thread-676::DEBUG::2012-10-15 14:14:58,258::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.3774dc69-8ba3-456e-b584-4c08e3ba3826`ReqID=`3f960418-4369-442c-bc37-e50c2a4efe83`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-676::DEBUG::2012-10-15 14:14:58,258::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.3774dc69-8ba3-456e-b584-4c08e3ba3826' for lock type 'shared'
>Thread-676::DEBUG::2012-10-15 14:14:58,259::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.3774dc69-8ba3-456e-b584-4c08e3ba3826' is free. Now locking as 'shared' (1 active user)
>Thread-676::DEBUG::2012-10-15 14:14:58,259::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.3774dc69-8ba3-456e-b584-4c08e3ba3826`ReqID=`3f960418-4369-442c-bc37-e50c2a4efe83`::Granted request
>Thread-676::DEBUG::2012-10-15 14:14:58,259::task::817::TaskManager.Task::(resourceAcquired) Task=`bd2eaec3-7f7e-40fc-be49-c605f6507119`::_resourcesAcquired: Storage.3774dc69-8ba3-456e-b584-4c08e3ba3826 (shared)
>Thread-676::DEBUG::2012-10-15 14:14:58,260::task::978::TaskManager.Task::(_decref) Task=`bd2eaec3-7f7e-40fc-be49-c605f6507119`::ref 1 aborting False
>Thread-676::DEBUG::2012-10-15 14:14:58,275::task::740::TaskManager.Task::(_save) Task=`bd2eaec3-7f7e-40fc-be49-c605f6507119`::_save: orig /rhev/data-center/e42f70cc-802e-46be-b931-867450cc6282/mastersd/master/tasks/bd2eaec3-7f7e-40fc-be49-c605f6507119 temp /rhev/data-center/e42f70cc-802e-46be-b931-867450cc6282/mastersd/master/tasks/bd2eaec3-7f7e-40fc-be49-c605f6507119.temp
>Thread-676::DEBUG::2012-10-15 14:14:58,345::taskManager::66::TaskManager::(scheduleJob) scheduled job createVolume for task bd2eaec3-7f7e-40fc-be49-c605f6507119 
>Thread-676::INFO::2012-10-15 14:14:58,346::logUtils::39::dispatcher::(wrapper) Run and protect: createVolume, Return response: None
>Thread-676::DEBUG::2012-10-15 14:14:58,346::task::1167::TaskManager.Task::(prepare) Task=`bd2eaec3-7f7e-40fc-be49-c605f6507119`::Prepare: 1 jobs exist, move to acquiring
>Thread-676::DEBUG::2012-10-15 14:14:58,346::task::588::TaskManager.Task::(_updateState) Task=`bd2eaec3-7f7e-40fc-be49-c605f6507119`::moving from state preparing -> state acquiring
>Thread-676::DEBUG::2012-10-15 14:14:58,347::task::740::TaskManager.Task::(_save) Task=`bd2eaec3-7f7e-40fc-be49-c605f6507119`::_save: orig /rhev/data-center/e42f70cc-802e-46be-b931-867450cc6282/mastersd/master/tasks/bd2eaec3-7f7e-40fc-be49-c605f6507119 temp /rhev/data-center/e42f70cc-802e-46be-b931-867450cc6282/mastersd/master/tasks/bd2eaec3-7f7e-40fc-be49-c605f6507119.temp
>Thread-676::DEBUG::2012-10-15 14:14:58,468::task::588::TaskManager.Task::(_updateState) Task=`bd2eaec3-7f7e-40fc-be49-c605f6507119`::moving from state acquiring -> state queued
>Thread-676::DEBUG::2012-10-15 14:14:58,468::task::740::TaskManager.Task::(_save) Task=`bd2eaec3-7f7e-40fc-be49-c605f6507119`::_save: orig /rhev/data-center/e42f70cc-802e-46be-b931-867450cc6282/mastersd/master/tasks/bd2eaec3-7f7e-40fc-be49-c605f6507119 temp /rhev/data-center/e42f70cc-802e-46be-b931-867450cc6282/mastersd/master/tasks/bd2eaec3-7f7e-40fc-be49-c605f6507119.temp
>Thread-676::DEBUG::2012-10-15 14:14:58,575::taskManager::48::TaskManager::(_queueTask) queueing task: bd2eaec3-7f7e-40fc-be49-c605f6507119
>Thread-676::DEBUG::2012-10-15 14:14:58,575::taskManager::54::TaskManager::(_queueTask) task queued: bd2eaec3-7f7e-40fc-be49-c605f6507119
>bcad671a-d35f-4254-9b5d-bfe710aa2c34::DEBUG::2012-10-15 14:14:58,575::threadPool::67::Misc.ThreadPool::(setRunningTask) Number of running tasks: 1
>Thread-676::DEBUG::2012-10-15 14:14:58,575::task::1169::TaskManager.Task::(prepare) Task=`bd2eaec3-7f7e-40fc-be49-c605f6507119`::returning
>bd2eaec3-7f7e-40fc-be49-c605f6507119::DEBUG::2012-10-15 14:14:58,576::threadPool::212::Misc.ThreadPool.WorkerThread::(run) Task: bd2eaec3-7f7e-40fc-be49-c605f6507119 running: <bound method Task.commit of <storage.task.Task instance at 0x7f2f3c37e710>> with: None
>Thread-676::DEBUG::2012-10-15 14:14:58,576::task::978::TaskManager.Task::(_decref) Task=`bd2eaec3-7f7e-40fc-be49-c605f6507119`::ref 0 aborting False
>bd2eaec3-7f7e-40fc-be49-c605f6507119::DEBUG::2012-10-15 14:14:58,576::task::1181::TaskManager.Task::(commit) Task=`bd2eaec3-7f7e-40fc-be49-c605f6507119`::Commiting task: bd2eaec3-7f7e-40fc-be49-c605f6507119
>bd2eaec3-7f7e-40fc-be49-c605f6507119::DEBUG::2012-10-15 14:14:58,577::task::588::TaskManager.Task::(_updateState) Task=`bd2eaec3-7f7e-40fc-be49-c605f6507119`::moving from state queued -> state running
>bd2eaec3-7f7e-40fc-be49-c605f6507119::DEBUG::2012-10-15 14:14:58,578::task::740::TaskManager.Task::(_save) Task=`bd2eaec3-7f7e-40fc-be49-c605f6507119`::_save: orig /rhev/data-center/e42f70cc-802e-46be-b931-867450cc6282/mastersd/master/tasks/bd2eaec3-7f7e-40fc-be49-c605f6507119 temp /rhev/data-center/e42f70cc-802e-46be-b931-867450cc6282/mastersd/master/tasks/bd2eaec3-7f7e-40fc-be49-c605f6507119.temp
>Thread-677::DEBUG::2012-10-15 14:14:58,652::BindingXMLRPC::171::vds::(wrapper) [10.35.70.46]
>Thread-677::DEBUG::2012-10-15 14:14:58,652::task::588::TaskManager.Task::(_updateState) Task=`97173c69-9870-48d1-8d72-1beff10e1bfb`::moving from state init -> state preparing
>Thread-677::INFO::2012-10-15 14:14:58,653::logUtils::37::dispatcher::(wrapper) Run and protect: createVolume(sdUUID='3774dc69-8ba3-456e-b584-4c08e3ba3826', spUUID='e42f70cc-802e-46be-b931-867450cc6282', imgUUID='e81e194e-1401-43aa-9a06-f467461fbd7e', size='10240', volFormat=4, preallocate=2, diskType=2, volUUID='57b3092a-199b-44cf-9b33-897508229458', desc='', srcImgUUID='00000000-0000-0000-0000-000000000000', srcVolUUID='00000000-0000-0000-0000-000000000000')
>Thread-677::INFO::2012-10-15 14:14:58,653::fileSD::227::Storage.StorageDomain::(validate) sdUUID=3774dc69-8ba3-456e-b584-4c08e3ba3826
>Thread-677::DEBUG::2012-10-15 14:14:58,656::persistentDict::226::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=DataDomain01', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=DataCenter01', 'POOL_DOMAINS=602b2bde-9a66-4fc3-91ef-8a85894c087c:Attached,3774dc69-8ba3-456e-b584-4c08e3ba3826:Active', 'POOL_SPM_ID=1', 'POOL_SPM_LVER=0', 'POOL_UUID=e42f70cc-802e-46be-b931-867450cc6282', 'REMOTE_PATH=tiger.qa.lab.tlv.redhat.com:/export/storage_l2Xi_4_nfs_20121015144737844796', 'ROLE=Master', 'SDUUID=3774dc69-8ba3-456e-b584-4c08e3ba3826', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=9dc2700e4368e38013a83258e3ccf7d3ab2f6288']
>Thread-677::DEBUG::2012-10-15 14:14:58,657::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.3774dc69-8ba3-456e-b584-4c08e3ba3826`ReqID=`53c8dc2b-22f1-4f45-9113-940639cfaf04`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-677::DEBUG::2012-10-15 14:14:58,657::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.3774dc69-8ba3-456e-b584-4c08e3ba3826' for lock type 'shared'
>Thread-677::DEBUG::2012-10-15 14:14:58,658::resourceManager::504::ResourceManager::(registerResource) Resource 'Storage.3774dc69-8ba3-456e-b584-4c08e3ba3826' found in shared state and queue is empty, Joining current shared lock (2 active users)
>Thread-677::DEBUG::2012-10-15 14:14:58,658::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.3774dc69-8ba3-456e-b584-4c08e3ba3826`ReqID=`53c8dc2b-22f1-4f45-9113-940639cfaf04`::Granted request
>Thread-677::DEBUG::2012-10-15 14:14:58,658::task::817::TaskManager.Task::(resourceAcquired) Task=`97173c69-9870-48d1-8d72-1beff10e1bfb`::_resourcesAcquired: Storage.3774dc69-8ba3-456e-b584-4c08e3ba3826 (shared)
>Thread-677::DEBUG::2012-10-15 14:14:58,659::task::978::TaskManager.Task::(_decref) Task=`97173c69-9870-48d1-8d72-1beff10e1bfb`::ref 1 aborting False
>Thread-677::DEBUG::2012-10-15 14:14:58,671::task::740::TaskManager.Task::(_save) Task=`97173c69-9870-48d1-8d72-1beff10e1bfb`::_save: orig /rhev/data-center/e42f70cc-802e-46be-b931-867450cc6282/mastersd/master/tasks/97173c69-9870-48d1-8d72-1beff10e1bfb temp /rhev/data-center/e42f70cc-802e-46be-b931-867450cc6282/mastersd/master/tasks/97173c69-9870-48d1-8d72-1beff10e1bfb.temp
>bd2eaec3-7f7e-40fc-be49-c605f6507119::DEBUG::2012-10-15 14:14:58,696::task::892::TaskManager.Task::(_runJobs) Task=`bd2eaec3-7f7e-40fc-be49-c605f6507119`::Task.run: running job 0: createVolume: <bound method StoragePool.createVolume of <storage.sp.StoragePool object at 0x7f2f3c470890>> (args: ('3774dc69-8ba3-456e-b584-4c08e3ba3826', 'ffc59ea3-64f7-4fbf-ae9a-889a6efbf331', 2244608, 5, 2, 2, 'f6ee3a1c-e0e3-470c-a175-63c17eafb0bd', '', '00000000-0000-0000-0000-000000000000', '00000000-0000-0000-0000-000000000000') kwargs: {})
>bd2eaec3-7f7e-40fc-be49-c605f6507119::DEBUG::2012-10-15 14:14:58,696::task::317::TaskManager.Task::(run) Task=`bd2eaec3-7f7e-40fc-be49-c605f6507119`::Job.run: running createVolume: <bound method StoragePool.createVolume of <storage.sp.StoragePool object at 0x7f2f3c470890>> (args: ('3774dc69-8ba3-456e-b584-4c08e3ba3826', 'ffc59ea3-64f7-4fbf-ae9a-889a6efbf331', 2244608, 5, 2, 2, 'f6ee3a1c-e0e3-470c-a175-63c17eafb0bd', '', '00000000-0000-0000-0000-000000000000', '00000000-0000-0000-0000-000000000000') kwargs: {}) callback None
>bd2eaec3-7f7e-40fc-be49-c605f6507119::DEBUG::2012-10-15 14:14:58,697::resourceManager::175::ResourceManager.Request::(__init__) ResName=`3774dc69-8ba3-456e-b584-4c08e3ba3826_imageNS.ffc59ea3-64f7-4fbf-ae9a-889a6efbf331`ReqID=`f67c4aa1-2d34-4f58-a03d-646045e3d474`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>bd2eaec3-7f7e-40fc-be49-c605f6507119::DEBUG::2012-10-15 14:14:58,697::resourceManager::486::ResourceManager::(registerResource) Trying to register resource '3774dc69-8ba3-456e-b584-4c08e3ba3826_imageNS.ffc59ea3-64f7-4fbf-ae9a-889a6efbf331' for lock type 'exclusive'
>bd2eaec3-7f7e-40fc-be49-c605f6507119::DEBUG::2012-10-15 14:14:58,698::resourceFactories::119::Storage.ResourcesFactories::(__getResourceCandidatesList) Image ffc59ea3-64f7-4fbf-ae9a-889a6efbf331 does not exist in domain 3774dc69-8ba3-456e-b584-4c08e3ba3826
>bd2eaec3-7f7e-40fc-be49-c605f6507119::DEBUG::2012-10-15 14:14:58,699::resourceManager::528::ResourceManager::(registerResource) Resource '3774dc69-8ba3-456e-b584-4c08e3ba3826_imageNS.ffc59ea3-64f7-4fbf-ae9a-889a6efbf331' is free. Now locking as 'exclusive' (1 active user)
>bd2eaec3-7f7e-40fc-be49-c605f6507119::DEBUG::2012-10-15 14:14:58,699::resourceManager::212::ResourceManager.Request::(grant) ResName=`3774dc69-8ba3-456e-b584-4c08e3ba3826_imageNS.ffc59ea3-64f7-4fbf-ae9a-889a6efbf331`ReqID=`f67c4aa1-2d34-4f58-a03d-646045e3d474`::Granted request
>bd2eaec3-7f7e-40fc-be49-c605f6507119::INFO::2012-10-15 14:14:58,699::image::94::Storage.Image::(create) Create placeholder /rhev/data-center/e42f70cc-802e-46be-b931-867450cc6282/3774dc69-8ba3-456e-b584-4c08e3ba3826/images/ffc59ea3-64f7-4fbf-ae9a-889a6efbf331 for image's volumes
>bd2eaec3-7f7e-40fc-be49-c605f6507119::DEBUG::2012-10-15 14:14:58,700::task::740::TaskManager.Task::(_save) Task=`bd2eaec3-7f7e-40fc-be49-c605f6507119`::_save: orig /rhev/data-center/e42f70cc-802e-46be-b931-867450cc6282/mastersd/master/tasks/bd2eaec3-7f7e-40fc-be49-c605f6507119 temp /rhev/data-center/e42f70cc-802e-46be-b931-867450cc6282/mastersd/master/tasks/bd2eaec3-7f7e-40fc-be49-c605f6507119.temp
>Thread-677::DEBUG::2012-10-15 14:14:58,786::taskManager::66::TaskManager::(scheduleJob) scheduled job createVolume for task 97173c69-9870-48d1-8d72-1beff10e1bfb 
>Thread-677::INFO::2012-10-15 14:14:58,786::logUtils::39::dispatcher::(wrapper) Run and protect: createVolume, Return response: None
>Thread-677::DEBUG::2012-10-15 14:14:58,786::task::1167::TaskManager.Task::(prepare) Task=`97173c69-9870-48d1-8d72-1beff10e1bfb`::Prepare: 1 jobs exist, move to acquiring
>Thread-677::DEBUG::2012-10-15 14:14:58,787::task::588::TaskManager.Task::(_updateState) Task=`97173c69-9870-48d1-8d72-1beff10e1bfb`::moving from state preparing -> state acquiring
>Thread-677::DEBUG::2012-10-15 14:14:58,787::task::740::TaskManager.Task::(_save) Task=`97173c69-9870-48d1-8d72-1beff10e1bfb`::_save: orig /rhev/data-center/e42f70cc-802e-46be-b931-867450cc6282/mastersd/master/tasks/97173c69-9870-48d1-8d72-1beff10e1bfb temp /rhev/data-center/e42f70cc-802e-46be-b931-867450cc6282/mastersd/master/tasks/97173c69-9870-48d1-8d72-1beff10e1bfb.temp
>Thread-677::DEBUG::2012-10-15 14:14:58,964::task::588::TaskManager.Task::(_updateState) Task=`97173c69-9870-48d1-8d72-1beff10e1bfb`::moving from state acquiring -> state queued
>Thread-677::DEBUG::2012-10-15 14:14:58,965::task::740::TaskManager.Task::(_save) Task=`97173c69-9870-48d1-8d72-1beff10e1bfb`::_save: orig /rhev/data-center/e42f70cc-802e-46be-b931-867450cc6282/mastersd/master/tasks/97173c69-9870-48d1-8d72-1beff10e1bfb temp /rhev/data-center/e42f70cc-802e-46be-b931-867450cc6282/mastersd/master/tasks/97173c69-9870-48d1-8d72-1beff10e1bfb.temp
>bd2eaec3-7f7e-40fc-be49-c605f6507119::INFO::2012-10-15 14:14:58,972::volume::449::Storage.Volume::(create) Creating volume f6ee3a1c-e0e3-470c-a175-63c17eafb0bd
>bd2eaec3-7f7e-40fc-be49-c605f6507119::DEBUG::2012-10-15 14:14:58,973::task::740::TaskManager.Task::(_save) Task=`bd2eaec3-7f7e-40fc-be49-c605f6507119`::_save: orig /rhev/data-center/e42f70cc-802e-46be-b931-867450cc6282/mastersd/master/tasks/bd2eaec3-7f7e-40fc-be49-c605f6507119 temp /rhev/data-center/e42f70cc-802e-46be-b931-867450cc6282/mastersd/master/tasks/bd2eaec3-7f7e-40fc-be49-c605f6507119.temp
>Thread-677::DEBUG::2012-10-15 14:14:59,169::taskManager::48::TaskManager::(_queueTask) queueing task: 97173c69-9870-48d1-8d72-1beff10e1bfb
>Thread-677::DEBUG::2012-10-15 14:14:59,169::taskManager::54::TaskManager::(_queueTask) task queued: 97173c69-9870-48d1-8d72-1beff10e1bfb
>Thread-3::DEBUG::2012-10-15 14:14:59,169::threadPool::67::Misc.ThreadPool::(setRunningTask) Number of running tasks: 2
>Thread-677::DEBUG::2012-10-15 14:14:59,170::task::1169::TaskManager.Task::(prepare) Task=`97173c69-9870-48d1-8d72-1beff10e1bfb`::returning
>97173c69-9870-48d1-8d72-1beff10e1bfb::DEBUG::2012-10-15 14:14:59,170::threadPool::212::Misc.ThreadPool.WorkerThread::(run) Task: 97173c69-9870-48d1-8d72-1beff10e1bfb running: <bound method Task.commit of <storage.task.Task instance at 0x7f2f3c3aa758>> with: None
>Thread-677::DEBUG::2012-10-15 14:14:59,170::task::978::TaskManager.Task::(_decref) Task=`97173c69-9870-48d1-8d72-1beff10e1bfb`::ref 0 aborting False
>97173c69-9870-48d1-8d72-1beff10e1bfb::DEBUG::2012-10-15 14:14:59,171::task::1181::TaskManager.Task::(commit) Task=`97173c69-9870-48d1-8d72-1beff10e1bfb`::Commiting task: 97173c69-9870-48d1-8d72-1beff10e1bfb
>97173c69-9870-48d1-8d72-1beff10e1bfb::DEBUG::2012-10-15 14:14:59,171::task::588::TaskManager.Task::(_updateState) Task=`97173c69-9870-48d1-8d72-1beff10e1bfb`::moving from state queued -> state running
>97173c69-9870-48d1-8d72-1beff10e1bfb::DEBUG::2012-10-15 14:14:59,172::task::740::TaskManager.Task::(_save) Task=`97173c69-9870-48d1-8d72-1beff10e1bfb`::_save: orig /rhev/data-center/e42f70cc-802e-46be-b931-867450cc6282/mastersd/master/tasks/97173c69-9870-48d1-8d72-1beff10e1bfb temp /rhev/data-center/e42f70cc-802e-46be-b931-867450cc6282/mastersd/master/tasks/97173c69-9870-48d1-8d72-1beff10e1bfb.temp
>bd2eaec3-7f7e-40fc-be49-c605f6507119::DEBUG::2012-10-15 14:14:59,320::task::740::TaskManager.Task::(_save) Task=`bd2eaec3-7f7e-40fc-be49-c605f6507119`::_save: orig /rhev/data-center/e42f70cc-802e-46be-b931-867450cc6282/mastersd/master/tasks/bd2eaec3-7f7e-40fc-be49-c605f6507119 temp /rhev/data-center/e42f70cc-802e-46be-b931-867450cc6282/mastersd/master/tasks/bd2eaec3-7f7e-40fc-be49-c605f6507119.temp
>97173c69-9870-48d1-8d72-1beff10e1bfb::DEBUG::2012-10-15 14:14:59,373::task::892::TaskManager.Task::(_runJobs) Task=`97173c69-9870-48d1-8d72-1beff10e1bfb`::Task.run: running job 0: createVolume: <bound method StoragePool.createVolume of <storage.sp.StoragePool object at 0x7f2f3c470890>> (args: ('3774dc69-8ba3-456e-b584-4c08e3ba3826', 'e81e194e-1401-43aa-9a06-f467461fbd7e', 20, 4, 2, 2, '57b3092a-199b-44cf-9b33-897508229458', '', '00000000-0000-0000-0000-000000000000', '00000000-0000-0000-0000-000000000000') kwargs: {})
>97173c69-9870-48d1-8d72-1beff10e1bfb::DEBUG::2012-10-15 14:14:59,374::task::317::TaskManager.Task::(run) Task=`97173c69-9870-48d1-8d72-1beff10e1bfb`::Job.run: running createVolume: <bound method StoragePool.createVolume of <storage.sp.StoragePool object at 0x7f2f3c470890>> (args: ('3774dc69-8ba3-456e-b584-4c08e3ba3826', 'e81e194e-1401-43aa-9a06-f467461fbd7e', 20, 4, 2, 2, '57b3092a-199b-44cf-9b33-897508229458', '', '00000000-0000-0000-0000-000000000000', '00000000-0000-0000-0000-000000000000') kwargs: {}) callback None
>97173c69-9870-48d1-8d72-1beff10e1bfb::DEBUG::2012-10-15 14:14:59,374::resourceManager::175::ResourceManager.Request::(__init__) ResName=`3774dc69-8ba3-456e-b584-4c08e3ba3826_imageNS.e81e194e-1401-43aa-9a06-f467461fbd7e`ReqID=`3d429cd1-f5d4-4921-848b-a930c1608213`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>97173c69-9870-48d1-8d72-1beff10e1bfb::DEBUG::2012-10-15 14:14:59,375::resourceManager::486::ResourceManager::(registerResource) Trying to register resource '3774dc69-8ba3-456e-b584-4c08e3ba3826_imageNS.e81e194e-1401-43aa-9a06-f467461fbd7e' for lock type 'exclusive'
>97173c69-9870-48d1-8d72-1beff10e1bfb::DEBUG::2012-10-15 14:14:59,376::resourceFactories::119::Storage.ResourcesFactories::(__getResourceCandidatesList) Image e81e194e-1401-43aa-9a06-f467461fbd7e does not exist in domain 3774dc69-8ba3-456e-b584-4c08e3ba3826
>97173c69-9870-48d1-8d72-1beff10e1bfb::DEBUG::2012-10-15 14:14:59,376::resourceManager::528::ResourceManager::(registerResource) Resource '3774dc69-8ba3-456e-b584-4c08e3ba3826_imageNS.e81e194e-1401-43aa-9a06-f467461fbd7e' is free. Now locking as 'exclusive' (1 active user)
>97173c69-9870-48d1-8d72-1beff10e1bfb::DEBUG::2012-10-15 14:14:59,376::resourceManager::212::ResourceManager.Request::(grant) ResName=`3774dc69-8ba3-456e-b584-4c08e3ba3826_imageNS.e81e194e-1401-43aa-9a06-f467461fbd7e`ReqID=`3d429cd1-f5d4-4921-848b-a930c1608213`::Granted request
>97173c69-9870-48d1-8d72-1beff10e1bfb::INFO::2012-10-15 14:14:59,377::image::94::Storage.Image::(create) Create placeholder /rhev/data-center/e42f70cc-802e-46be-b931-867450cc6282/3774dc69-8ba3-456e-b584-4c08e3ba3826/images/e81e194e-1401-43aa-9a06-f467461fbd7e for image's volumes
>97173c69-9870-48d1-8d72-1beff10e1bfb::DEBUG::2012-10-15 14:14:59,378::task::740::TaskManager.Task::(_save) Task=`97173c69-9870-48d1-8d72-1beff10e1bfb`::_save: orig /rhev/data-center/e42f70cc-802e-46be-b931-867450cc6282/mastersd/master/tasks/97173c69-9870-48d1-8d72-1beff10e1bfb temp /rhev/data-center/e42f70cc-802e-46be-b931-867450cc6282/mastersd/master/tasks/97173c69-9870-48d1-8d72-1beff10e1bfb.temp
>Thread-679::DEBUG::2012-10-15 14:14:59,857::BindingXMLRPC::171::vds::(wrapper) [10.35.70.46]
>Thread-679::DEBUG::2012-10-15 14:14:59,857::task::588::TaskManager.Task::(_updateState) Task=`5315bff8-9405-49bf-8a1d-ad0a5b918489`::moving from state init -> state preparing
>Thread-679::INFO::2012-10-15 14:14:59,858::logUtils::37::dispatcher::(wrapper) Run and protect: getAllTasksStatuses(spUUID=None, options=None)
>Thread-679::DEBUG::2012-10-15 14:14:59,858::taskManager::103::TaskManager::(getAllTasksStatuses) Entry.
>Thread-679::DEBUG::2012-10-15 14:14:59,858::taskManager::93::TaskManager::(getTaskStatus) Entry. taskID: bd2eaec3-7f7e-40fc-be49-c605f6507119
>Thread-679::DEBUG::2012-10-15 14:14:59,859::taskManager::96::TaskManager::(getTaskStatus) Return. Response: {'code': 0, 'message': 'Task is initializing', 'taskState': 'running', 'taskResult': '', 'taskID': 'bd2eaec3-7f7e-40fc-be49-c605f6507119'}
>Thread-679::DEBUG::2012-10-15 14:14:59,859::taskManager::93::TaskManager::(getTaskStatus) Entry. taskID: 97173c69-9870-48d1-8d72-1beff10e1bfb
>Thread-679::DEBUG::2012-10-15 14:14:59,859::taskManager::96::TaskManager::(getTaskStatus) Return. Response: {'code': 0, 'message': 'Task is initializing', 'taskState': 'running', 'taskResult': '', 'taskID': '97173c69-9870-48d1-8d72-1beff10e1bfb'}
>Thread-679::DEBUG::2012-10-15 14:14:59,859::taskManager::112::TaskManager::(getAllTasksStatuses) Return: {'bd2eaec3-7f7e-40fc-be49-c605f6507119': {'code': 0, 'message': 'Task is initializing', 'taskState': 'running', 'taskResult': '', 'taskID': 'bd2eaec3-7f7e-40fc-be49-c605f6507119'}, '97173c69-9870-48d1-8d72-1beff10e1bfb': {'code': 0, 'message': 'Task is initializing', 'taskState': 'running', 'taskResult': '', 'taskID': '97173c69-9870-48d1-8d72-1beff10e1bfb'}}
>Thread-679::INFO::2012-10-15 14:14:59,860::logUtils::39::dispatcher::(wrapper) Run and protect: getAllTasksStatuses, Return response: {'allTasksStatus': {'bd2eaec3-7f7e-40fc-be49-c605f6507119': {'code': 0, 'message': 'Task is initializing', 'taskState': 'running', 'taskResult': '', 'taskID': 'bd2eaec3-7f7e-40fc-be49-c605f6507119'}, '97173c69-9870-48d1-8d72-1beff10e1bfb': {'code': 0, 'message': 'Task is initializing', 'taskState': 'running', 'taskResult': '', 'taskID': '97173c69-9870-48d1-8d72-1beff10e1bfb'}}}
>Thread-679::DEBUG::2012-10-15 14:14:59,860::task::1172::TaskManager.Task::(prepare) Task=`5315bff8-9405-49bf-8a1d-ad0a5b918489`::finished: {'allTasksStatus': {'bd2eaec3-7f7e-40fc-be49-c605f6507119': {'code': 0, 'message': 'Task is initializing', 'taskState': 'running', 'taskResult': '', 'taskID': 'bd2eaec3-7f7e-40fc-be49-c605f6507119'}, '97173c69-9870-48d1-8d72-1beff10e1bfb': {'code': 0, 'message': 'Task is initializing', 'taskState': 'running', 'taskResult': '', 'taskID': '97173c69-9870-48d1-8d72-1beff10e1bfb'}}}
>Thread-679::DEBUG::2012-10-15 14:14:59,860::task::588::TaskManager.Task::(_updateState) Task=`5315bff8-9405-49bf-8a1d-ad0a5b918489`::moving from state preparing -> state finished
>Thread-679::DEBUG::2012-10-15 14:14:59,861::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-679::DEBUG::2012-10-15 14:14:59,861::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-679::DEBUG::2012-10-15 14:14:59,861::task::978::TaskManager.Task::(_decref) Task=`5315bff8-9405-49bf-8a1d-ad0a5b918489`::ref 0 aborting False
>97173c69-9870-48d1-8d72-1beff10e1bfb::INFO::2012-10-15 14:14:59,966::volume::449::Storage.Volume::(create) Creating volume 57b3092a-199b-44cf-9b33-897508229458
>97173c69-9870-48d1-8d72-1beff10e1bfb::DEBUG::2012-10-15 14:14:59,967::task::740::TaskManager.Task::(_save) Task=`97173c69-9870-48d1-8d72-1beff10e1bfb`::_save: orig /rhev/data-center/e42f70cc-802e-46be-b931-867450cc6282/mastersd/master/tasks/97173c69-9870-48d1-8d72-1beff10e1bfb temp /rhev/data-center/e42f70cc-802e-46be-b931-867450cc6282/mastersd/master/tasks/97173c69-9870-48d1-8d72-1beff10e1bfb.temp
>bd2eaec3-7f7e-40fc-be49-c605f6507119::INFO::2012-10-15 14:15:00,058::fileVolume::153::Storage.Volume::(_create) Request to create RAW volume /rhev/data-center/e42f70cc-802e-46be-b931-867450cc6282/3774dc69-8ba3-456e-b584-4c08e3ba3826/images/ffc59ea3-64f7-4fbf-ae9a-889a6efbf331/f6ee3a1c-e0e3-470c-a175-63c17eafb0bd with size = 2244608 sectors
>bd2eaec3-7f7e-40fc-be49-c605f6507119::DEBUG::2012-10-15 14:15:00,125::task::740::TaskManager.Task::(_save) Task=`bd2eaec3-7f7e-40fc-be49-c605f6507119`::_save: orig /rhev/data-center/e42f70cc-802e-46be-b931-867450cc6282/mastersd/master/tasks/bd2eaec3-7f7e-40fc-be49-c605f6507119 temp /rhev/data-center/e42f70cc-802e-46be-b931-867450cc6282/mastersd/master/tasks/bd2eaec3-7f7e-40fc-be49-c605f6507119.temp
>97173c69-9870-48d1-8d72-1beff10e1bfb::DEBUG::2012-10-15 14:15:00,297::task::740::TaskManager.Task::(_save) Task=`97173c69-9870-48d1-8d72-1beff10e1bfb`::_save: orig /rhev/data-center/e42f70cc-802e-46be-b931-867450cc6282/mastersd/master/tasks/97173c69-9870-48d1-8d72-1beff10e1bfb temp /rhev/data-center/e42f70cc-802e-46be-b931-867450cc6282/mastersd/master/tasks/97173c69-9870-48d1-8d72-1beff10e1bfb.temp
>bd2eaec3-7f7e-40fc-be49-c605f6507119::DEBUG::2012-10-15 14:15:00,689::fileVolume::395::Storage.Volume::(newVolumeLease) Initializing volume lease volUUID=f6ee3a1c-e0e3-470c-a175-63c17eafb0bd sdUUID=3774dc69-8ba3-456e-b584-4c08e3ba3826, metaId=('/rhev/data-center/e42f70cc-802e-46be-b931-867450cc6282/3774dc69-8ba3-456e-b584-4c08e3ba3826/images/ffc59ea3-64f7-4fbf-ae9a-889a6efbf331/f6ee3a1c-e0e3-470c-a175-63c17eafb0bd',)
>97173c69-9870-48d1-8d72-1beff10e1bfb::INFO::2012-10-15 14:15:00,763::fileVolume::153::Storage.Volume::(_create) Request to create COW volume /rhev/data-center/e42f70cc-802e-46be-b931-867450cc6282/3774dc69-8ba3-456e-b584-4c08e3ba3826/images/e81e194e-1401-43aa-9a06-f467461fbd7e/57b3092a-199b-44cf-9b33-897508229458 with size = 20 sectors
>97173c69-9870-48d1-8d72-1beff10e1bfb::DEBUG::2012-10-15 14:15:00,764::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/qemu-img create -f qcow2 /rhev/data-center/e42f70cc-802e-46be-b931-867450cc6282/3774dc69-8ba3-456e-b584-4c08e3ba3826/images/e81e194e-1401-43aa-9a06-f467461fbd7e/57b3092a-199b-44cf-9b33-897508229458 10K' (cwd None)
>Thread-680::DEBUG::2012-10-15 14:15:00,798::task::588::TaskManager.Task::(_updateState) Task=`9accb2aa-dd1f-4e23-85c8-bf3e1e860067`::moving from state init -> state preparing
>Thread-680::INFO::2012-10-15 14:15:00,799::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>bd2eaec3-7f7e-40fc-be49-c605f6507119::DEBUG::2012-10-15 14:15:00,800::task::740::TaskManager.Task::(_save) Task=`bd2eaec3-7f7e-40fc-be49-c605f6507119`::_save: orig /rhev/data-center/e42f70cc-802e-46be-b931-867450cc6282/mastersd/master/tasks/bd2eaec3-7f7e-40fc-be49-c605f6507119 temp /rhev/data-center/e42f70cc-802e-46be-b931-867450cc6282/mastersd/master/tasks/bd2eaec3-7f7e-40fc-be49-c605f6507119.temp
>Thread-680::INFO::2012-10-15 14:15:00,801::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'3774dc69-8ba3-456e-b584-4c08e3ba3826': {'delay': '0.0021231174469', 'lastCheck': 1350306900.1088181, 'code': 0, 'valid': True}}
>Thread-680::DEBUG::2012-10-15 14:15:00,801::task::1172::TaskManager.Task::(prepare) Task=`9accb2aa-dd1f-4e23-85c8-bf3e1e860067`::finished: {'3774dc69-8ba3-456e-b584-4c08e3ba3826': {'delay': '0.0021231174469', 'lastCheck': 1350306900.1088181, 'code': 0, 'valid': True}}
>Thread-680::DEBUG::2012-10-15 14:15:00,802::task::588::TaskManager.Task::(_updateState) Task=`9accb2aa-dd1f-4e23-85c8-bf3e1e860067`::moving from state preparing -> state finished
>Thread-680::DEBUG::2012-10-15 14:15:00,802::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-680::DEBUG::2012-10-15 14:15:00,803::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-680::DEBUG::2012-10-15 14:15:00,803::task::978::TaskManager.Task::(_decref) Task=`9accb2aa-dd1f-4e23-85c8-bf3e1e860067`::ref 0 aborting False
>Thread-681::DEBUG::2012-10-15 14:15:00,826::libvirtvm::243::vm.Vm::(_getDiskStats) vmId=`2e915601-b596-4108-9c3b-9d85ecbe1600`::Disk hdc stats not available
>97173c69-9870-48d1-8d72-1beff10e1bfb::DEBUG::2012-10-15 14:15:00,848::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
>97173c69-9870-48d1-8d72-1beff10e1bfb::DEBUG::2012-10-15 14:15:00,914::task::740::TaskManager.Task::(_save) Task=`97173c69-9870-48d1-8d72-1beff10e1bfb`::_save: orig /rhev/data-center/e42f70cc-802e-46be-b931-867450cc6282/mastersd/master/tasks/97173c69-9870-48d1-8d72-1beff10e1bfb temp /rhev/data-center/e42f70cc-802e-46be-b931-867450cc6282/mastersd/master/tasks/97173c69-9870-48d1-8d72-1beff10e1bfb.temp
>bd2eaec3-7f7e-40fc-be49-c605f6507119::DEBUG::2012-10-15 14:15:01,165::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource '3774dc69-8ba3-456e-b584-4c08e3ba3826_imageNS.ffc59ea3-64f7-4fbf-ae9a-889a6efbf331'
>bd2eaec3-7f7e-40fc-be49-c605f6507119::DEBUG::2012-10-15 14:15:01,166::resourceManager::553::ResourceManager::(releaseResource) Released resource '3774dc69-8ba3-456e-b584-4c08e3ba3826_imageNS.ffc59ea3-64f7-4fbf-ae9a-889a6efbf331' (0 active users)
>bd2eaec3-7f7e-40fc-be49-c605f6507119::DEBUG::2012-10-15 14:15:01,166::resourceManager::558::ResourceManager::(releaseResource) Resource '3774dc69-8ba3-456e-b584-4c08e3ba3826_imageNS.ffc59ea3-64f7-4fbf-ae9a-889a6efbf331' is free, finding out if anyone is waiting for it.
>bd2eaec3-7f7e-40fc-be49-c605f6507119::DEBUG::2012-10-15 14:15:01,166::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource '3774dc69-8ba3-456e-b584-4c08e3ba3826_imageNS.ffc59ea3-64f7-4fbf-ae9a-889a6efbf331', Clearing records.
>bd2eaec3-7f7e-40fc-be49-c605f6507119::DEBUG::2012-10-15 14:15:01,167::task::588::TaskManager.Task::(_updateState) Task=`bd2eaec3-7f7e-40fc-be49-c605f6507119`::moving from state running -> state finished
>bd2eaec3-7f7e-40fc-be49-c605f6507119::DEBUG::2012-10-15 14:15:01,167::task::740::TaskManager.Task::(_save) Task=`bd2eaec3-7f7e-40fc-be49-c605f6507119`::_save: orig /rhev/data-center/e42f70cc-802e-46be-b931-867450cc6282/mastersd/master/tasks/bd2eaec3-7f7e-40fc-be49-c605f6507119 temp /rhev/data-center/e42f70cc-802e-46be-b931-867450cc6282/mastersd/master/tasks/bd2eaec3-7f7e-40fc-be49-c605f6507119.temp
>97173c69-9870-48d1-8d72-1beff10e1bfb::DEBUG::2012-10-15 14:15:01,473::fileVolume::395::Storage.Volume::(newVolumeLease) Initializing volume lease volUUID=57b3092a-199b-44cf-9b33-897508229458 sdUUID=3774dc69-8ba3-456e-b584-4c08e3ba3826, metaId=('/rhev/data-center/e42f70cc-802e-46be-b931-867450cc6282/3774dc69-8ba3-456e-b584-4c08e3ba3826/images/e81e194e-1401-43aa-9a06-f467461fbd7e/57b3092a-199b-44cf-9b33-897508229458',)
>bd2eaec3-7f7e-40fc-be49-c605f6507119::DEBUG::2012-10-15 14:15:01,572::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.3774dc69-8ba3-456e-b584-4c08e3ba3826': < ResourceRef 'Storage.3774dc69-8ba3-456e-b584-4c08e3ba3826', isValid: 'True' obj: 'None'>}
>bd2eaec3-7f7e-40fc-be49-c605f6507119::DEBUG::2012-10-15 14:15:01,572::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>bd2eaec3-7f7e-40fc-be49-c605f6507119::DEBUG::2012-10-15 14:15:01,572::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.3774dc69-8ba3-456e-b584-4c08e3ba3826'
>bd2eaec3-7f7e-40fc-be49-c605f6507119::DEBUG::2012-10-15 14:15:01,573::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.3774dc69-8ba3-456e-b584-4c08e3ba3826' (1 active users)
>bd2eaec3-7f7e-40fc-be49-c605f6507119::DEBUG::2012-10-15 14:15:01,573::task::900::TaskManager.Task::(_runJobs) Task=`bd2eaec3-7f7e-40fc-be49-c605f6507119`::Task.run: exit - success: result {'uuid': 'f6ee3a1c-e0e3-470c-a175-63c17eafb0bd'}
>bd2eaec3-7f7e-40fc-be49-c605f6507119::DEBUG::2012-10-15 14:15:01,573::task::978::TaskManager.Task::(_decref) Task=`bd2eaec3-7f7e-40fc-be49-c605f6507119`::ref 0 aborting False
>bd2eaec3-7f7e-40fc-be49-c605f6507119::DEBUG::2012-10-15 14:15:01,574::threadPool::67::Misc.ThreadPool::(setRunningTask) Number of running tasks: 1
>97173c69-9870-48d1-8d72-1beff10e1bfb::DEBUG::2012-10-15 14:15:01,580::task::740::TaskManager.Task::(_save) Task=`97173c69-9870-48d1-8d72-1beff10e1bfb`::_save: orig /rhev/data-center/e42f70cc-802e-46be-b931-867450cc6282/mastersd/master/tasks/97173c69-9870-48d1-8d72-1beff10e1bfb temp /rhev/data-center/e42f70cc-802e-46be-b931-867450cc6282/mastersd/master/tasks/97173c69-9870-48d1-8d72-1beff10e1bfb.temp
>97173c69-9870-48d1-8d72-1beff10e1bfb::DEBUG::2012-10-15 14:15:01,817::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource '3774dc69-8ba3-456e-b584-4c08e3ba3826_imageNS.e81e194e-1401-43aa-9a06-f467461fbd7e'
>97173c69-9870-48d1-8d72-1beff10e1bfb::DEBUG::2012-10-15 14:15:01,817::resourceManager::553::ResourceManager::(releaseResource) Released resource '3774dc69-8ba3-456e-b584-4c08e3ba3826_imageNS.e81e194e-1401-43aa-9a06-f467461fbd7e' (0 active users)
>97173c69-9870-48d1-8d72-1beff10e1bfb::DEBUG::2012-10-15 14:15:01,818::resourceManager::558::ResourceManager::(releaseResource) Resource '3774dc69-8ba3-456e-b584-4c08e3ba3826_imageNS.e81e194e-1401-43aa-9a06-f467461fbd7e' is free, finding out if anyone is waiting for it.
>97173c69-9870-48d1-8d72-1beff10e1bfb::DEBUG::2012-10-15 14:15:01,818::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource '3774dc69-8ba3-456e-b584-4c08e3ba3826_imageNS.e81e194e-1401-43aa-9a06-f467461fbd7e', Clearing records.
>97173c69-9870-48d1-8d72-1beff10e1bfb::DEBUG::2012-10-15 14:15:01,818::task::588::TaskManager.Task::(_updateState) Task=`97173c69-9870-48d1-8d72-1beff10e1bfb`::moving from state running -> state finished
>97173c69-9870-48d1-8d72-1beff10e1bfb::DEBUG::2012-10-15 14:15:01,819::task::740::TaskManager.Task::(_save) Task=`97173c69-9870-48d1-8d72-1beff10e1bfb`::_save: orig /rhev/data-center/e42f70cc-802e-46be-b931-867450cc6282/mastersd/master/tasks/97173c69-9870-48d1-8d72-1beff10e1bfb temp /rhev/data-center/e42f70cc-802e-46be-b931-867450cc6282/mastersd/master/tasks/97173c69-9870-48d1-8d72-1beff10e1bfb.temp
>97173c69-9870-48d1-8d72-1beff10e1bfb::DEBUG::2012-10-15 14:15:02,064::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.3774dc69-8ba3-456e-b584-4c08e3ba3826': < ResourceRef 'Storage.3774dc69-8ba3-456e-b584-4c08e3ba3826', isValid: 'True' obj: 'None'>}
>97173c69-9870-48d1-8d72-1beff10e1bfb::DEBUG::2012-10-15 14:15:02,065::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>97173c69-9870-48d1-8d72-1beff10e1bfb::DEBUG::2012-10-15 14:15:02,065::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.3774dc69-8ba3-456e-b584-4c08e3ba3826'
>97173c69-9870-48d1-8d72-1beff10e1bfb::DEBUG::2012-10-15 14:15:02,065::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.3774dc69-8ba3-456e-b584-4c08e3ba3826' (0 active users)
>97173c69-9870-48d1-8d72-1beff10e1bfb::DEBUG::2012-10-15 14:15:02,066::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.3774dc69-8ba3-456e-b584-4c08e3ba3826' is free, finding out if anyone is waiting for it.
>97173c69-9870-48d1-8d72-1beff10e1bfb::DEBUG::2012-10-15 14:15:02,066::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.3774dc69-8ba3-456e-b584-4c08e3ba3826', Clearing records.
>97173c69-9870-48d1-8d72-1beff10e1bfb::DEBUG::2012-10-15 14:15:02,066::task::900::TaskManager.Task::(_runJobs) Task=`97173c69-9870-48d1-8d72-1beff10e1bfb`::Task.run: exit - success: result {'uuid': '57b3092a-199b-44cf-9b33-897508229458'}
>97173c69-9870-48d1-8d72-1beff10e1bfb::DEBUG::2012-10-15 14:15:02,067::task::978::TaskManager.Task::(_decref) Task=`97173c69-9870-48d1-8d72-1beff10e1bfb`::ref 0 aborting False
>97173c69-9870-48d1-8d72-1beff10e1bfb::DEBUG::2012-10-15 14:15:02,067::threadPool::67::Misc.ThreadPool::(setRunningTask) Number of running tasks: 0
>Thread-683::DEBUG::2012-10-15 14:15:04,824::BindingXMLRPC::171::vds::(wrapper) [10.35.70.46]
>Thread-683::DEBUG::2012-10-15 14:15:04,824::task::588::TaskManager.Task::(_updateState) Task=`e0379af5-2fce-4508-88c6-740810679a58`::moving from state init -> state preparing
>Thread-683::INFO::2012-10-15 14:15:04,824::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='e42f70cc-802e-46be-b931-867450cc6282', options=None)
>Thread-683::INFO::2012-10-15 14:15:04,825::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 0}}
>Thread-683::DEBUG::2012-10-15 14:15:04,825::task::1172::TaskManager.Task::(prepare) Task=`e0379af5-2fce-4508-88c6-740810679a58`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 0}}
>Thread-683::DEBUG::2012-10-15 14:15:04,825::task::588::TaskManager.Task::(_updateState) Task=`e0379af5-2fce-4508-88c6-740810679a58`::moving from state preparing -> state finished
>Thread-683::DEBUG::2012-10-15 14:15:04,826::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-683::DEBUG::2012-10-15 14:15:04,826::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-683::DEBUG::2012-10-15 14:15:04,826::task::978::TaskManager.Task::(_decref) Task=`e0379af5-2fce-4508-88c6-740810679a58`::ref 0 aborting False
>Thread-684::DEBUG::2012-10-15 14:15:04,846::BindingXMLRPC::171::vds::(wrapper) [10.35.70.46]
>Thread-684::DEBUG::2012-10-15 14:15:04,846::task::588::TaskManager.Task::(_updateState) Task=`57b83615-b2ef-4266-9568-17d3eb19f70f`::moving from state init -> state preparing
>Thread-684::INFO::2012-10-15 14:15:04,846::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='e42f70cc-802e-46be-b931-867450cc6282', options=None)
>Thread-684::DEBUG::2012-10-15 14:15:04,847::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.e42f70cc-802e-46be-b931-867450cc6282`ReqID=`c0b6c5c9-095c-4946-aca7-ace3713376a2`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-684::DEBUG::2012-10-15 14:15:04,847::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282' for lock type 'shared'
>Thread-684::DEBUG::2012-10-15 14:15:04,848::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282' is free. Now locking as 'shared' (1 active user)
>Thread-684::DEBUG::2012-10-15 14:15:04,848::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.e42f70cc-802e-46be-b931-867450cc6282`ReqID=`c0b6c5c9-095c-4946-aca7-ace3713376a2`::Granted request
>Thread-684::DEBUG::2012-10-15 14:15:04,848::task::817::TaskManager.Task::(resourceAcquired) Task=`57b83615-b2ef-4266-9568-17d3eb19f70f`::_resourcesAcquired: Storage.e42f70cc-802e-46be-b931-867450cc6282 (shared)
>Thread-684::DEBUG::2012-10-15 14:15:04,849::task::978::TaskManager.Task::(_decref) Task=`57b83615-b2ef-4266-9568-17d3eb19f70f`::ref 1 aborting False
>Thread-684::INFO::2012-10-15 14:15:04,851::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '3774dc69-8ba3-456e-b584-4c08e3ba3826', 'name': 'DataCenter01', 'version': '3', 'domains': '602b2bde-9a66-4fc3-91ef-8a85894c087c:Attached,3774dc69-8ba3-456e-b584-4c08e3ba3826:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 0}, 'dominfo': {'602b2bde-9a66-4fc3-91ef-8a85894c087c': {'status': 'Attached'}, '3774dc69-8ba3-456e-b584-4c08e3ba3826': {'status': 'Active', 'diskfree': '1041588289536', 'alerts': [], 'disktotal': '1098974756864'}}}
>Thread-684::DEBUG::2012-10-15 14:15:04,851::task::1172::TaskManager.Task::(prepare) Task=`57b83615-b2ef-4266-9568-17d3eb19f70f`::finished: {'info': {'spm_id': 1, 'master_uuid': '3774dc69-8ba3-456e-b584-4c08e3ba3826', 'name': 'DataCenter01', 'version': '3', 'domains': '602b2bde-9a66-4fc3-91ef-8a85894c087c:Attached,3774dc69-8ba3-456e-b584-4c08e3ba3826:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 0}, 'dominfo': {'602b2bde-9a66-4fc3-91ef-8a85894c087c': {'status': 'Attached'}, '3774dc69-8ba3-456e-b584-4c08e3ba3826': {'status': 'Active', 'diskfree': '1041588289536', 'alerts': [], 'disktotal': '1098974756864'}}}
>Thread-684::DEBUG::2012-10-15 14:15:04,852::task::588::TaskManager.Task::(_updateState) Task=`57b83615-b2ef-4266-9568-17d3eb19f70f`::moving from state preparing -> state finished
>Thread-684::DEBUG::2012-10-15 14:15:04,852::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.e42f70cc-802e-46be-b931-867450cc6282': < ResourceRef 'Storage.e42f70cc-802e-46be-b931-867450cc6282', isValid: 'True' obj: 'None'>}
>Thread-684::DEBUG::2012-10-15 14:15:04,852::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-684::DEBUG::2012-10-15 14:15:04,852::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282'
>Thread-684::DEBUG::2012-10-15 14:15:04,853::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282' (0 active users)
>Thread-684::DEBUG::2012-10-15 14:15:04,853::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282' is free, finding out if anyone is waiting for it.
>Thread-684::DEBUG::2012-10-15 14:15:04,853::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282', Clearing records.
>Thread-684::DEBUG::2012-10-15 14:15:04,854::task::978::TaskManager.Task::(_decref) Task=`57b83615-b2ef-4266-9568-17d3eb19f70f`::ref 0 aborting False
>Thread-688::DEBUG::2012-10-15 14:15:09,884::BindingXMLRPC::171::vds::(wrapper) [10.35.70.46]
>Thread-688::DEBUG::2012-10-15 14:15:09,885::task::588::TaskManager.Task::(_updateState) Task=`1bde2da4-cf88-45c8-aa6a-75b593d1e0a1`::moving from state init -> state preparing
>Thread-688::INFO::2012-10-15 14:15:09,885::logUtils::37::dispatcher::(wrapper) Run and protect: getAllTasksStatuses(spUUID=None, options=None)
>Thread-688::DEBUG::2012-10-15 14:15:09,885::taskManager::103::TaskManager::(getAllTasksStatuses) Entry.
>Thread-688::DEBUG::2012-10-15 14:15:09,885::taskManager::93::TaskManager::(getTaskStatus) Entry. taskID: bd2eaec3-7f7e-40fc-be49-c605f6507119
>Thread-688::DEBUG::2012-10-15 14:15:09,886::taskManager::96::TaskManager::(getTaskStatus) Return. Response: {'code': 0, 'message': '1 jobs completed successfully', 'taskState': 'finished', 'taskResult': 'success', 'taskID': 'bd2eaec3-7f7e-40fc-be49-c605f6507119'}
>Thread-688::DEBUG::2012-10-15 14:15:09,886::taskManager::93::TaskManager::(getTaskStatus) Entry. taskID: 97173c69-9870-48d1-8d72-1beff10e1bfb
>Thread-688::DEBUG::2012-10-15 14:15:09,886::taskManager::96::TaskManager::(getTaskStatus) Return. Response: {'code': 0, 'message': '1 jobs completed successfully', 'taskState': 'finished', 'taskResult': 'success', 'taskID': '97173c69-9870-48d1-8d72-1beff10e1bfb'}
>Thread-688::DEBUG::2012-10-15 14:15:09,886::taskManager::112::TaskManager::(getAllTasksStatuses) Return: {'bd2eaec3-7f7e-40fc-be49-c605f6507119': {'code': 0, 'message': '1 jobs completed successfully', 'taskState': 'finished', 'taskResult': 'success', 'taskID': 'bd2eaec3-7f7e-40fc-be49-c605f6507119'}, '97173c69-9870-48d1-8d72-1beff10e1bfb': {'code': 0, 'message': '1 jobs completed successfully', 'taskState': 'finished', 'taskResult': 'success', 'taskID': '97173c69-9870-48d1-8d72-1beff10e1bfb'}}
>Thread-688::INFO::2012-10-15 14:15:09,887::logUtils::39::dispatcher::(wrapper) Run and protect: getAllTasksStatuses, Return response: {'allTasksStatus': {'bd2eaec3-7f7e-40fc-be49-c605f6507119': {'code': 0, 'message': '1 jobs completed successfully', 'taskState': 'finished', 'taskResult': 'success', 'taskID': 'bd2eaec3-7f7e-40fc-be49-c605f6507119'}, '97173c69-9870-48d1-8d72-1beff10e1bfb': {'code': 0, 'message': '1 jobs completed successfully', 'taskState': 'finished', 'taskResult': 'success', 'taskID': '97173c69-9870-48d1-8d72-1beff10e1bfb'}}}
>Thread-688::DEBUG::2012-10-15 14:15:09,887::task::1172::TaskManager.Task::(prepare) Task=`1bde2da4-cf88-45c8-aa6a-75b593d1e0a1`::finished: {'allTasksStatus': {'bd2eaec3-7f7e-40fc-be49-c605f6507119': {'code': 0, 'message': '1 jobs completed successfully', 'taskState': 'finished', 'taskResult': 'success', 'taskID': 'bd2eaec3-7f7e-40fc-be49-c605f6507119'}, '97173c69-9870-48d1-8d72-1beff10e1bfb': {'code': 0, 'message': '1 jobs completed successfully', 'taskState': 'finished', 'taskResult': 'success', 'taskID': '97173c69-9870-48d1-8d72-1beff10e1bfb'}}}
>Thread-688::DEBUG::2012-10-15 14:15:09,887::task::588::TaskManager.Task::(_updateState) Task=`1bde2da4-cf88-45c8-aa6a-75b593d1e0a1`::moving from state preparing -> state finished
>Thread-688::DEBUG::2012-10-15 14:15:09,888::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-688::DEBUG::2012-10-15 14:15:09,888::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-688::DEBUG::2012-10-15 14:15:09,888::task::978::TaskManager.Task::(_decref) Task=`1bde2da4-cf88-45c8-aa6a-75b593d1e0a1`::ref 0 aborting False
>Thread-689::DEBUG::2012-10-15 14:15:09,980::BindingXMLRPC::874::vds::(wrapper) client [10.35.70.46]::call vmHibernate with ('2e915601-b596-4108-9c3b-9d85ecbe1600', '3774dc69-8ba3-456e-b584-4c08e3ba3826,e42f70cc-802e-46be-b931-867450cc6282,ffc59ea3-64f7-4fbf-ae9a-889a6efbf331,f6ee3a1c-e0e3-470c-a175-63c17eafb0bd,e81e194e-1401-43aa-9a06-f467461fbd7e,57b3092a-199b-44cf-9b33-897508229458') {}
>Thread-689::DEBUG::2012-10-15 14:15:09,981::API::421::vds::(migrate) {'hiberVolHandle': '3774dc69-8ba3-456e-b584-4c08e3ba3826,e42f70cc-802e-46be-b931-867450cc6282,ffc59ea3-64f7-4fbf-ae9a-889a6efbf331,f6ee3a1c-e0e3-470c-a175-63c17eafb0bd,e81e194e-1401-43aa-9a06-f467461fbd7e,57b3092a-199b-44cf-9b33-897508229458', 'vmId': '2e915601-b596-4108-9c3b-9d85ecbe1600', 'mode': 'file'}
>Thread-690::DEBUG::2012-10-15 14:15:09,981::libvirtvm::243::vm.Vm::(_getDiskStats) vmId=`2e915601-b596-4108-9c3b-9d85ecbe1600`::Disk hdc stats not available
>Thread-689::DEBUG::2012-10-15 14:15:09,982::BindingXMLRPC::880::vds::(wrapper) return vmHibernate with {'status': {'message': 'Hibernation process starting', 'code': 0}}
>Thread-691::DEBUG::2012-10-15 14:15:10,063::BindingXMLRPC::171::vds::(wrapper) [10.35.70.46]
>Thread-691::DEBUG::2012-10-15 14:15:10,063::task::588::TaskManager.Task::(_updateState) Task=`82283102-fddd-44f7-b565-b41d21585df6`::moving from state init -> state preparing
>Thread-691::INFO::2012-10-15 14:15:10,064::logUtils::37::dispatcher::(wrapper) Run and protect: clearTask(taskID='bd2eaec3-7f7e-40fc-be49-c605f6507119', spUUID=None, options=None)
>Thread-691::DEBUG::2012-10-15 14:15:10,064::taskManager::161::TaskManager::(clearTask) Entry. taskID: bd2eaec3-7f7e-40fc-be49-c605f6507119
>Thread-690::DEBUG::2012-10-15 14:15:10,083::vm::155::vm.Vm::(_prepareGuest) vmId=`2e915601-b596-4108-9c3b-9d85ecbe1600`::Save State begins
>Thread-690::DEBUG::2012-10-15 14:15:10,083::guestIF::185::vm.Vm::(desktopLock) vmId=`2e915601-b596-4108-9c3b-9d85ecbe1600`::desktopLock called
>Thread-691::DEBUG::2012-10-15 14:15:10,125::taskManager::166::TaskManager::(clearTask) Return.
>Thread-691::INFO::2012-10-15 14:15:10,133::logUtils::39::dispatcher::(wrapper) Run and protect: clearTask, Return response: None
>Thread-691::DEBUG::2012-10-15 14:15:10,133::task::1172::TaskManager.Task::(prepare) Task=`82283102-fddd-44f7-b565-b41d21585df6`::finished: None
>Thread-691::DEBUG::2012-10-15 14:15:10,133::task::588::TaskManager.Task::(_updateState) Task=`82283102-fddd-44f7-b565-b41d21585df6`::moving from state preparing -> state finished
>Thread-691::DEBUG::2012-10-15 14:15:10,134::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-691::DEBUG::2012-10-15 14:15:10,134::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-691::DEBUG::2012-10-15 14:15:10,134::task::978::TaskManager.Task::(_decref) Task=`82283102-fddd-44f7-b565-b41d21585df6`::ref 0 aborting False
>Thread-692::DEBUG::2012-10-15 14:15:10,167::BindingXMLRPC::171::vds::(wrapper) [10.35.70.46]
>Thread-692::DEBUG::2012-10-15 14:15:10,183::task::588::TaskManager.Task::(_updateState) Task=`e2abd47d-8597-4faf-a0b3-f67e9beeb9f0`::moving from state init -> state preparing
>Thread-692::INFO::2012-10-15 14:15:10,184::logUtils::37::dispatcher::(wrapper) Run and protect: clearTask(taskID='97173c69-9870-48d1-8d72-1beff10e1bfb', spUUID=None, options=None)
>Thread-692::DEBUG::2012-10-15 14:15:10,184::taskManager::161::TaskManager::(clearTask) Entry. taskID: 97173c69-9870-48d1-8d72-1beff10e1bfb
>Thread-692::DEBUG::2012-10-15 14:15:10,243::taskManager::166::TaskManager::(clearTask) Return.
>Thread-692::INFO::2012-10-15 14:15:10,243::logUtils::39::dispatcher::(wrapper) Run and protect: clearTask, Return response: None
>Thread-692::DEBUG::2012-10-15 14:15:10,243::task::1172::TaskManager.Task::(prepare) Task=`e2abd47d-8597-4faf-a0b3-f67e9beeb9f0`::finished: None
>Thread-692::DEBUG::2012-10-15 14:15:10,244::task::588::TaskManager.Task::(_updateState) Task=`e2abd47d-8597-4faf-a0b3-f67e9beeb9f0`::moving from state preparing -> state finished
>Thread-692::DEBUG::2012-10-15 14:15:10,244::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-692::DEBUG::2012-10-15 14:15:10,244::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-692::DEBUG::2012-10-15 14:15:10,245::task::978::TaskManager.Task::(_decref) Task=`e2abd47d-8597-4faf-a0b3-f67e9beeb9f0`::ref 0 aborting False
>libvirtEventLoop::DEBUG::2012-10-15 14:15:10,360::libvirtvm::2481::vm.Vm::(_onLibvirtLifecycleEvent) vmId=`2e915601-b596-4108-9c3b-9d85ecbe1600`::event Suspended detail 0 opaque None
>Thread-690::DEBUG::2012-10-15 14:15:10,461::vm::220::vm.Vm::(run) vmId=`2e915601-b596-4108-9c3b-9d85ecbe1600`::migration semaphore acquired
>Thread-690::DEBUG::2012-10-15 14:15:10,670::utils::344::vm.Vm::(pause) vmId=`2e915601-b596-4108-9c3b-9d85ecbe1600`::Pause statistics collection
>Thread-690::DEBUG::2012-10-15 14:15:10,671::task::588::TaskManager.Task::(_updateState) Task=`c51a6742-4588-4980-9bf1-4b749ba88ea1`::moving from state init -> state preparing
>Thread-690::INFO::2012-10-15 14:15:10,671::logUtils::37::dispatcher::(wrapper) Run and protect: prepareImage(sdUUID='3774dc69-8ba3-456e-b584-4c08e3ba3826', spUUID='e42f70cc-802e-46be-b931-867450cc6282', imgUUID='ffc59ea3-64f7-4fbf-ae9a-889a6efbf331', volUUID='f6ee3a1c-e0e3-470c-a175-63c17eafb0bd')
>Thread-690::DEBUG::2012-10-15 14:15:10,672::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.3774dc69-8ba3-456e-b584-4c08e3ba3826`ReqID=`4fc7d3c7-14c3-4c19-ba69-1eedcc87b9f3`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-690::DEBUG::2012-10-15 14:15:10,672::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.3774dc69-8ba3-456e-b584-4c08e3ba3826' for lock type 'shared'
>Thread-690::DEBUG::2012-10-15 14:15:10,672::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.3774dc69-8ba3-456e-b584-4c08e3ba3826' is free. Now locking as 'shared' (1 active user)
>Thread-690::DEBUG::2012-10-15 14:15:10,673::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.3774dc69-8ba3-456e-b584-4c08e3ba3826`ReqID=`4fc7d3c7-14c3-4c19-ba69-1eedcc87b9f3`::Granted request
>Thread-690::DEBUG::2012-10-15 14:15:10,673::task::817::TaskManager.Task::(resourceAcquired) Task=`c51a6742-4588-4980-9bf1-4b749ba88ea1`::_resourcesAcquired: Storage.3774dc69-8ba3-456e-b584-4c08e3ba3826 (shared)
>Thread-690::DEBUG::2012-10-15 14:15:10,673::task::978::TaskManager.Task::(_decref) Task=`c51a6742-4588-4980-9bf1-4b749ba88ea1`::ref 1 aborting False
>Thread-690::DEBUG::2012-10-15 14:15:10,674::fileVolume::552::Storage.Volume::(validateVolumePath) validate path for f6ee3a1c-e0e3-470c-a175-63c17eafb0bd
>Thread-690::INFO::2012-10-15 14:15:10,682::image::319::Storage.Image::(getChain) sdUUID=3774dc69-8ba3-456e-b584-4c08e3ba3826 imgUUID=ffc59ea3-64f7-4fbf-ae9a-889a6efbf331 chain=[<storage.fileVolume.FileVolume object at 0x7f2f3c4a4210>] 
>Thread-690::INFO::2012-10-15 14:15:10,685::logUtils::39::dispatcher::(wrapper) Run and protect: prepareImage, Return response: {'path': '/rhev/data-center/e42f70cc-802e-46be-b931-867450cc6282/3774dc69-8ba3-456e-b584-4c08e3ba3826/images/ffc59ea3-64f7-4fbf-ae9a-889a6efbf331/f6ee3a1c-e0e3-470c-a175-63c17eafb0bd', 'chain': [{'path': '/rhev/data-center/e42f70cc-802e-46be-b931-867450cc6282/3774dc69-8ba3-456e-b584-4c08e3ba3826/images/ffc59ea3-64f7-4fbf-ae9a-889a6efbf331/f6ee3a1c-e0e3-470c-a175-63c17eafb0bd', 'domainID': '3774dc69-8ba3-456e-b584-4c08e3ba3826', 'volumeID': 'f6ee3a1c-e0e3-470c-a175-63c17eafb0bd', 'imageID': 'ffc59ea3-64f7-4fbf-ae9a-889a6efbf331'}]}
>Thread-690::DEBUG::2012-10-15 14:15:10,686::task::1172::TaskManager.Task::(prepare) Task=`c51a6742-4588-4980-9bf1-4b749ba88ea1`::finished: {'path': '/rhev/data-center/e42f70cc-802e-46be-b931-867450cc6282/3774dc69-8ba3-456e-b584-4c08e3ba3826/images/ffc59ea3-64f7-4fbf-ae9a-889a6efbf331/f6ee3a1c-e0e3-470c-a175-63c17eafb0bd', 'chain': [{'path': '/rhev/data-center/e42f70cc-802e-46be-b931-867450cc6282/3774dc69-8ba3-456e-b584-4c08e3ba3826/images/ffc59ea3-64f7-4fbf-ae9a-889a6efbf331/f6ee3a1c-e0e3-470c-a175-63c17eafb0bd', 'domainID': '3774dc69-8ba3-456e-b584-4c08e3ba3826', 'volumeID': 'f6ee3a1c-e0e3-470c-a175-63c17eafb0bd', 'imageID': 'ffc59ea3-64f7-4fbf-ae9a-889a6efbf331'}]}
>Thread-690::DEBUG::2012-10-15 14:15:10,691::task::588::TaskManager.Task::(_updateState) Task=`c51a6742-4588-4980-9bf1-4b749ba88ea1`::moving from state preparing -> state finished
>Thread-690::DEBUG::2012-10-15 14:15:10,695::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.3774dc69-8ba3-456e-b584-4c08e3ba3826': < ResourceRef 'Storage.3774dc69-8ba3-456e-b584-4c08e3ba3826', isValid: 'True' obj: 'None'>}
>Thread-690::DEBUG::2012-10-15 14:15:10,699::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-690::DEBUG::2012-10-15 14:15:10,705::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.3774dc69-8ba3-456e-b584-4c08e3ba3826'
>Thread-690::DEBUG::2012-10-15 14:15:10,710::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.3774dc69-8ba3-456e-b584-4c08e3ba3826' (0 active users)
>Thread-690::DEBUG::2012-10-15 14:15:10,714::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.3774dc69-8ba3-456e-b584-4c08e3ba3826' is free, finding out if anyone is waiting for it.
>Thread-690::DEBUG::2012-10-15 14:15:10,718::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.3774dc69-8ba3-456e-b584-4c08e3ba3826', Clearing records.
>Thread-690::DEBUG::2012-10-15 14:15:10,723::task::978::TaskManager.Task::(_decref) Task=`c51a6742-4588-4980-9bf1-4b749ba88ea1`::ref 0 aborting False
>Thread-690::INFO::2012-10-15 14:15:10,727::clientIF::242::vds::(prepareVolumePath) prepared volume path: /rhev/data-center/e42f70cc-802e-46be-b931-867450cc6282/3774dc69-8ba3-456e-b584-4c08e3ba3826/images/ffc59ea3-64f7-4fbf-ae9a-889a6efbf331/f6ee3a1c-e0e3-470c-a175-63c17eafb0bd
>Thread-693::DEBUG::2012-10-15 14:15:11,114::task::588::TaskManager.Task::(_updateState) Task=`9c3bc224-50b8-482f-893a-fd32521774fa`::moving from state init -> state preparing
>Thread-693::INFO::2012-10-15 14:15:11,120::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-693::INFO::2012-10-15 14:15:11,125::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'3774dc69-8ba3-456e-b584-4c08e3ba3826': {'delay': '0.00208616256714', 'lastCheck': 1350306910.116039, 'code': 0, 'valid': True}}
>Thread-693::DEBUG::2012-10-15 14:15:11,129::task::1172::TaskManager.Task::(prepare) Task=`9c3bc224-50b8-482f-893a-fd32521774fa`::finished: {'3774dc69-8ba3-456e-b584-4c08e3ba3826': {'delay': '0.00208616256714', 'lastCheck': 1350306910.116039, 'code': 0, 'valid': True}}
>Thread-693::DEBUG::2012-10-15 14:15:11,134::task::588::TaskManager.Task::(_updateState) Task=`9c3bc224-50b8-482f-893a-fd32521774fa`::moving from state preparing -> state finished
>Thread-693::DEBUG::2012-10-15 14:15:11,138::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-693::DEBUG::2012-10-15 14:15:11,143::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-693::DEBUG::2012-10-15 14:15:11,148::task::978::TaskManager.Task::(_decref) Task=`9c3bc224-50b8-482f-893a-fd32521774fa`::ref 0 aborting False
>Thread-694::DEBUG::2012-10-15 14:15:11,277::libvirtvm::243::vm.Vm::(_getDiskStats) vmId=`2e915601-b596-4108-9c3b-9d85ecbe1600`::Disk hdc stats not available
>Thread-690::DEBUG::2012-10-15 14:15:11,333::task::588::TaskManager.Task::(_updateState) Task=`e4d8ba80-4109-4e5f-b553-99a197cfce75`::moving from state init -> state preparing
>Thread-690::INFO::2012-10-15 14:15:11,338::logUtils::37::dispatcher::(wrapper) Run and protect: teardownImage(sdUUID='3774dc69-8ba3-456e-b584-4c08e3ba3826', spUUID='e42f70cc-802e-46be-b931-867450cc6282', imgUUID='ffc59ea3-64f7-4fbf-ae9a-889a6efbf331', volUUID=None)
>Thread-690::DEBUG::2012-10-15 14:15:11,345::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.3774dc69-8ba3-456e-b584-4c08e3ba3826`ReqID=`7e542ee1-d89d-467d-a170-0dce4e1da003`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-690::DEBUG::2012-10-15 14:15:11,349::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.3774dc69-8ba3-456e-b584-4c08e3ba3826' for lock type 'shared'
>Thread-690::DEBUG::2012-10-15 14:15:11,355::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.3774dc69-8ba3-456e-b584-4c08e3ba3826' is free. Now locking as 'shared' (1 active user)
>Thread-690::DEBUG::2012-10-15 14:15:11,359::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.3774dc69-8ba3-456e-b584-4c08e3ba3826`ReqID=`7e542ee1-d89d-467d-a170-0dce4e1da003`::Granted request
>Thread-690::DEBUG::2012-10-15 14:15:11,366::task::817::TaskManager.Task::(resourceAcquired) Task=`e4d8ba80-4109-4e5f-b553-99a197cfce75`::_resourcesAcquired: Storage.3774dc69-8ba3-456e-b584-4c08e3ba3826 (shared)
>Thread-690::DEBUG::2012-10-15 14:15:11,370::task::978::TaskManager.Task::(_decref) Task=`e4d8ba80-4109-4e5f-b553-99a197cfce75`::ref 1 aborting False
>Thread-690::DEBUG::2012-10-15 14:15:11,400::fileVolume::552::Storage.Volume::(validateVolumePath) validate path for f6ee3a1c-e0e3-470c-a175-63c17eafb0bd
>Thread-690::ERROR::2012-10-15 14:15:11,410::task::853::TaskManager.Task::(_setError) Task=`e4d8ba80-4109-4e5f-b553-99a197cfce75`::Unexpected error
>Traceback (most recent call last):
>  File "/usr/share/vdsm/storage/task.py", line 861, in _run
>    return fn(*args, **kargs)
>  File "/usr/share/vdsm/logUtils.py", line 38, in wrapper
>    res = f(*args, **kwargs)
>  File "/usr/share/vdsm/storage/hsm.py", line 2814, in teardownImage
>    img.teardown(sdUUID, imgUUID, volUUID)
>  File "/usr/share/vdsm/storage/image.py", line 354, in teardown
>    chain = self.getChain(sdUUID, imgUUID, volUUID)
>  File "/usr/share/vdsm/storage/image.py", line 286, in getChain
>    uuidlist = volclass.getImageVolumes(self.repoPath, sdUUID, imgUUID)
>  File "/usr/share/vdsm/storage/fileVolume.py", line 387, in getImageVolumes
>    produceVolume(imgUUID, volid).
>  File "/usr/share/vdsm/storage/fileSD.py", line 174, in produceVolume
>    return fileVolume.FileVolume(repoPath, self.sdUUID, imgUUID, volUUID)
>  File "/usr/share/vdsm/storage/fileVolume.py", line 71, in __init__
>    volume.Volume.__init__(self, repoPath, sdUUID, imgUUID, volUUID)
>  File "/usr/share/vdsm/storage/volume.py", line 127, in __init__
>    self.validate()
>  File "/usr/share/vdsm/storage/volume.py", line 140, in validate
>    self.validateVolumePath()
>  File "/usr/share/vdsm/storage/fileVolume.py", line 557, in validateVolumePath
>    raise se.VolumeDoesNotExist(self.volUUID)
>VolumeDoesNotExist: Volume does not exist: ('f6ee3a1c-e0e3-470c-a175-63c17eafb0bd',)
>Thread-690::DEBUG::2012-10-15 14:15:11,430::task::872::TaskManager.Task::(_run) Task=`e4d8ba80-4109-4e5f-b553-99a197cfce75`::Task._run: e4d8ba80-4109-4e5f-b553-99a197cfce75 ('3774dc69-8ba3-456e-b584-4c08e3ba3826', 'e42f70cc-802e-46be-b931-867450cc6282', 'ffc59ea3-64f7-4fbf-ae9a-889a6efbf331') {} failed - stopping task
>Thread-690::DEBUG::2012-10-15 14:15:11,434::task::1199::TaskManager.Task::(stop) Task=`e4d8ba80-4109-4e5f-b553-99a197cfce75`::stopping in state preparing (force False)
>Thread-690::DEBUG::2012-10-15 14:15:11,439::task::978::TaskManager.Task::(_decref) Task=`e4d8ba80-4109-4e5f-b553-99a197cfce75`::ref 1 aborting True
>Thread-690::INFO::2012-10-15 14:15:11,443::task::1157::TaskManager.Task::(prepare) Task=`e4d8ba80-4109-4e5f-b553-99a197cfce75`::aborting: Task is aborted: 'Volume does not exist' - code 201
>Thread-690::DEBUG::2012-10-15 14:15:11,448::task::1162::TaskManager.Task::(prepare) Task=`e4d8ba80-4109-4e5f-b553-99a197cfce75`::Prepare: aborted: Volume does not exist
>Thread-690::DEBUG::2012-10-15 14:15:11,452::task::978::TaskManager.Task::(_decref) Task=`e4d8ba80-4109-4e5f-b553-99a197cfce75`::ref 0 aborting True
>Thread-690::DEBUG::2012-10-15 14:15:11,456::task::913::TaskManager.Task::(_doAbort) Task=`e4d8ba80-4109-4e5f-b553-99a197cfce75`::Task._doAbort: force False
>Thread-690::DEBUG::2012-10-15 14:15:11,460::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-690::DEBUG::2012-10-15 14:15:11,464::task::588::TaskManager.Task::(_updateState) Task=`e4d8ba80-4109-4e5f-b553-99a197cfce75`::moving from state preparing -> state aborting
>Thread-690::DEBUG::2012-10-15 14:15:11,469::task::537::TaskManager.Task::(__state_aborting) Task=`e4d8ba80-4109-4e5f-b553-99a197cfce75`::_aborting: recover policy none
>Thread-690::DEBUG::2012-10-15 14:15:11,473::task::588::TaskManager.Task::(_updateState) Task=`e4d8ba80-4109-4e5f-b553-99a197cfce75`::moving from state aborting -> state failed
>Thread-690::DEBUG::2012-10-15 14:15:11,477::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.3774dc69-8ba3-456e-b584-4c08e3ba3826': < ResourceRef 'Storage.3774dc69-8ba3-456e-b584-4c08e3ba3826', isValid: 'True' obj: 'None'>}
>Thread-690::DEBUG::2012-10-15 14:15:11,481::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-690::DEBUG::2012-10-15 14:15:11,487::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.3774dc69-8ba3-456e-b584-4c08e3ba3826'
>Thread-690::DEBUG::2012-10-15 14:15:11,492::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.3774dc69-8ba3-456e-b584-4c08e3ba3826' (0 active users)
>Thread-690::DEBUG::2012-10-15 14:15:11,496::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.3774dc69-8ba3-456e-b584-4c08e3ba3826' is free, finding out if anyone is waiting for it.
>Thread-690::DEBUG::2012-10-15 14:15:11,500::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.3774dc69-8ba3-456e-b584-4c08e3ba3826', Clearing records.
>Thread-690::ERROR::2012-10-15 14:15:11,506::dispatcher::66::Storage.Dispatcher.Protect::(run) {'status': {'message': "Volume does not exist: ('f6ee3a1c-e0e3-470c-a175-63c17eafb0bd',)", 'code': 201}}
>Thread-690::DEBUG::2012-10-15 14:15:11,510::utils::351::vm.Vm::(cont) vmId=`2e915601-b596-4108-9c3b-9d85ecbe1600`::Resume statistics collection
>Thread-690::ERROR::2012-10-15 14:15:11,516::vm::179::vm.Vm::(_recover) vmId=`2e915601-b596-4108-9c3b-9d85ecbe1600`::internal error unable to execute QEMU command 'migrate': An undefined error has ocurred
>Thread-690::ERROR::2012-10-15 14:15:11,521::vm::830::vm.Vm::(cont) vmId=`2e915601-b596-4108-9c3b-9d85ecbe1600`::cannot cont while Saving State
>Thread-690::ERROR::2012-10-15 14:15:11,902::vm::243::vm.Vm::(run) vmId=`2e915601-b596-4108-9c3b-9d85ecbe1600`::Failed to migrate
>Traceback (most recent call last):
>  File "/usr/share/vdsm/vm.py", line 226, in run
>    self._startUnderlyingMigration()
>  File "/usr/share/vdsm/libvirtvm.py", line 412, in _startUnderlyingMigration
>    self._vm._dom.save(fname)
>  File "/usr/share/vdsm/libvirtvm.py", line 494, in f
>    ret = attr(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/vdsm/libvirtconnection.py", line 82, in wrapper
>    ret = f(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/libvirt.py", line 1215, in save
>    if ret == -1: raise libvirtError ('virDomainSave() failed', dom=self)
>libvirtError: internal error unable to execute QEMU command 'migrate': An undefined error has ocurred
>Thread-696::DEBUG::2012-10-15 14:15:13,522::BindingXMLRPC::874::vds::(wrapper) client [10.35.70.46]::call vmGetStats with ('2e915601-b596-4108-9c3b-9d85ecbe1600',) {}
>Thread-696::DEBUG::2012-10-15 14:15:13,522::libvirtvm::243::vm.Vm::(_getDiskStats) vmId=`2e915601-b596-4108-9c3b-9d85ecbe1600`::Disk hdc stats not available
>Thread-696::DEBUG::2012-10-15 14:15:13,523::BindingXMLRPC::880::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Paused', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'pid': '3837', 'displayIp': '0', 'displayPort': u'5900', 'session': 'Unknown', 'displaySecurePort': u'5901', 'timeOffset': '-43200', 'hash': '7924989815650995483', 'pauseCode': 'NOERR', 'clientIp': '', 'kvmEnable': 'true', 'network': {}, 'vmId': '2e915601-b596-4108-9c3b-9d85ecbe1600', 'displayType': 'qxl', 'cpuUser': '6.50', 'disks': {u'vda': {'readLatency': '0', 'apparentsize': '1073741824', 'writeLatency': '0', 'imageID': '72387989-9478-428a-842a-ff012b850fa3', 'flushLatency': '0', 'readRate': '0.00', 'truesize': '0', 'writeRate': '0.00'}, u'hdc': {'flushLatency': '0', 'readLatency': '0', 'writeLatency': '0'}}, 'monitorResponse': '0', 'statsAge': '1.00', 'cpuIdle': '93.50', 'elapsedTime': '89', 'vmType': 'kvm', 'cpuSys': '0.00', 'appsList': [], 'guestIPs': '', 'nice': ''}]}
>Thread-697::DEBUG::2012-10-15 14:15:14,922::BindingXMLRPC::171::vds::(wrapper) [10.35.70.46]
>Thread-697::DEBUG::2012-10-15 14:15:14,922::task::588::TaskManager.Task::(_updateState) Task=`0f5ae384-a667-4b87-ae40-a1f45c0ee402`::moving from state init -> state preparing
>Thread-697::INFO::2012-10-15 14:15:14,922::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='e42f70cc-802e-46be-b931-867450cc6282', options=None)
>Thread-697::INFO::2012-10-15 14:15:14,923::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 0}}
>Thread-697::DEBUG::2012-10-15 14:15:14,923::task::1172::TaskManager.Task::(prepare) Task=`0f5ae384-a667-4b87-ae40-a1f45c0ee402`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 0}}
>Thread-697::DEBUG::2012-10-15 14:15:14,923::task::588::TaskManager.Task::(_updateState) Task=`0f5ae384-a667-4b87-ae40-a1f45c0ee402`::moving from state preparing -> state finished
>Thread-697::DEBUG::2012-10-15 14:15:14,924::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-697::DEBUG::2012-10-15 14:15:14,924::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-697::DEBUG::2012-10-15 14:15:14,924::task::978::TaskManager.Task::(_decref) Task=`0f5ae384-a667-4b87-ae40-a1f45c0ee402`::ref 0 aborting False
>Thread-698::DEBUG::2012-10-15 14:15:14,943::BindingXMLRPC::171::vds::(wrapper) [10.35.70.46]
>Thread-698::DEBUG::2012-10-15 14:15:14,944::task::588::TaskManager.Task::(_updateState) Task=`ce3ff37a-78ff-4584-bae3-55b5d2d6a9b8`::moving from state init -> state preparing
>Thread-698::INFO::2012-10-15 14:15:14,944::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='e42f70cc-802e-46be-b931-867450cc6282', options=None)
>Thread-698::DEBUG::2012-10-15 14:15:14,945::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.e42f70cc-802e-46be-b931-867450cc6282`ReqID=`4ee9e0f8-77db-434f-9ff9-be592235dcdd`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-698::DEBUG::2012-10-15 14:15:14,945::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282' for lock type 'shared'
>Thread-698::DEBUG::2012-10-15 14:15:14,945::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282' is free. Now locking as 'shared' (1 active user)
>Thread-698::DEBUG::2012-10-15 14:15:14,945::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.e42f70cc-802e-46be-b931-867450cc6282`ReqID=`4ee9e0f8-77db-434f-9ff9-be592235dcdd`::Granted request
>Thread-698::DEBUG::2012-10-15 14:15:14,946::task::817::TaskManager.Task::(resourceAcquired) Task=`ce3ff37a-78ff-4584-bae3-55b5d2d6a9b8`::_resourcesAcquired: Storage.e42f70cc-802e-46be-b931-867450cc6282 (shared)
>Thread-698::DEBUG::2012-10-15 14:15:14,946::task::978::TaskManager.Task::(_decref) Task=`ce3ff37a-78ff-4584-bae3-55b5d2d6a9b8`::ref 1 aborting False
>Thread-698::INFO::2012-10-15 14:15:14,948::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '3774dc69-8ba3-456e-b584-4c08e3ba3826', 'name': 'DataCenter01', 'version': '3', 'domains': '602b2bde-9a66-4fc3-91ef-8a85894c087c:Attached,3774dc69-8ba3-456e-b584-4c08e3ba3826:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 0}, 'dominfo': {'602b2bde-9a66-4fc3-91ef-8a85894c087c': {'status': 'Attached'}, '3774dc69-8ba3-456e-b584-4c08e3ba3826': {'status': 'Active', 'diskfree': '1041586192384', 'alerts': [], 'disktotal': '1098974756864'}}}
>Thread-698::DEBUG::2012-10-15 14:15:14,949::task::1172::TaskManager.Task::(prepare) Task=`ce3ff37a-78ff-4584-bae3-55b5d2d6a9b8`::finished: {'info': {'spm_id': 1, 'master_uuid': '3774dc69-8ba3-456e-b584-4c08e3ba3826', 'name': 'DataCenter01', 'version': '3', 'domains': '602b2bde-9a66-4fc3-91ef-8a85894c087c:Attached,3774dc69-8ba3-456e-b584-4c08e3ba3826:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 0}, 'dominfo': {'602b2bde-9a66-4fc3-91ef-8a85894c087c': {'status': 'Attached'}, '3774dc69-8ba3-456e-b584-4c08e3ba3826': {'status': 'Active', 'diskfree': '1041586192384', 'alerts': [], 'disktotal': '1098974756864'}}}
>Thread-698::DEBUG::2012-10-15 14:15:14,949::task::588::TaskManager.Task::(_updateState) Task=`ce3ff37a-78ff-4584-bae3-55b5d2d6a9b8`::moving from state preparing -> state finished
>Thread-698::DEBUG::2012-10-15 14:15:14,949::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.e42f70cc-802e-46be-b931-867450cc6282': < ResourceRef 'Storage.e42f70cc-802e-46be-b931-867450cc6282', isValid: 'True' obj: 'None'>}
>Thread-698::DEBUG::2012-10-15 14:15:14,950::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-698::DEBUG::2012-10-15 14:15:14,950::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282'
>Thread-698::DEBUG::2012-10-15 14:15:14,950::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282' (0 active users)
>Thread-698::DEBUG::2012-10-15 14:15:14,951::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282' is free, finding out if anyone is waiting for it.
>Thread-698::DEBUG::2012-10-15 14:15:14,951::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282', Clearing records.
>Thread-698::DEBUG::2012-10-15 14:15:14,951::task::978::TaskManager.Task::(_decref) Task=`ce3ff37a-78ff-4584-bae3-55b5d2d6a9b8`::ref 0 aborting False
>VM Channels Listener::DEBUG::2012-10-15 14:15:15,517::vmChannels::60::vds::(_handle_timeouts) Timeout on fileno 78.
>Thread-702::DEBUG::2012-10-15 14:15:21,640::task::588::TaskManager.Task::(_updateState) Task=`632f09c9-57e6-4a4a-9e1e-8688d9080c14`::moving from state init -> state preparing
>Thread-702::INFO::2012-10-15 14:15:21,641::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-702::INFO::2012-10-15 14:15:21,686::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'3774dc69-8ba3-456e-b584-4c08e3ba3826': {'delay': '0.00254678726196', 'lastCheck': 1350306920.1240699, 'code': 0, 'valid': True}}
>Thread-702::DEBUG::2012-10-15 14:15:21,686::task::1172::TaskManager.Task::(prepare) Task=`632f09c9-57e6-4a4a-9e1e-8688d9080c14`::finished: {'3774dc69-8ba3-456e-b584-4c08e3ba3826': {'delay': '0.00254678726196', 'lastCheck': 1350306920.1240699, 'code': 0, 'valid': True}}
>Thread-702::DEBUG::2012-10-15 14:15:21,687::task::588::TaskManager.Task::(_updateState) Task=`632f09c9-57e6-4a4a-9e1e-8688d9080c14`::moving from state preparing -> state finished
>Thread-702::DEBUG::2012-10-15 14:15:21,687::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-702::DEBUG::2012-10-15 14:15:21,687::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-702::DEBUG::2012-10-15 14:15:21,687::task::978::TaskManager.Task::(_decref) Task=`632f09c9-57e6-4a4a-9e1e-8688d9080c14`::ref 0 aborting False
>Thread-703::DEBUG::2012-10-15 14:15:21,719::libvirtvm::243::vm.Vm::(_getDiskStats) vmId=`2e915601-b596-4108-9c3b-9d85ecbe1600`::Disk hdc stats not available
>Thread-705::DEBUG::2012-10-15 14:15:25,020::BindingXMLRPC::171::vds::(wrapper) [10.35.70.46]
>Thread-705::DEBUG::2012-10-15 14:15:25,021::task::588::TaskManager.Task::(_updateState) Task=`1b2dd158-b0ef-4542-8e0c-c517f174fc89`::moving from state init -> state preparing
>Thread-705::INFO::2012-10-15 14:15:25,021::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='e42f70cc-802e-46be-b931-867450cc6282', options=None)
>Thread-705::INFO::2012-10-15 14:15:25,021::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 0}}
>Thread-705::DEBUG::2012-10-15 14:15:25,022::task::1172::TaskManager.Task::(prepare) Task=`1b2dd158-b0ef-4542-8e0c-c517f174fc89`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 0}}
>Thread-705::DEBUG::2012-10-15 14:15:25,022::task::588::TaskManager.Task::(_updateState) Task=`1b2dd158-b0ef-4542-8e0c-c517f174fc89`::moving from state preparing -> state finished
>Thread-705::DEBUG::2012-10-15 14:15:25,022::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-705::DEBUG::2012-10-15 14:15:25,022::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-705::DEBUG::2012-10-15 14:15:25,023::task::978::TaskManager.Task::(_decref) Task=`1b2dd158-b0ef-4542-8e0c-c517f174fc89`::ref 0 aborting False
>Thread-706::DEBUG::2012-10-15 14:15:25,042::BindingXMLRPC::171::vds::(wrapper) [10.35.70.46]
>Thread-706::DEBUG::2012-10-15 14:15:25,043::task::588::TaskManager.Task::(_updateState) Task=`38288ec9-8682-4aa3-be30-a02d53da939b`::moving from state init -> state preparing
>Thread-706::INFO::2012-10-15 14:15:25,043::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='e42f70cc-802e-46be-b931-867450cc6282', options=None)
>Thread-706::DEBUG::2012-10-15 14:15:25,044::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.e42f70cc-802e-46be-b931-867450cc6282`ReqID=`1ec4c684-5a52-408e-9f56-13702f6d0836`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-706::DEBUG::2012-10-15 14:15:25,044::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282' for lock type 'shared'
>Thread-706::DEBUG::2012-10-15 14:15:25,044::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282' is free. Now locking as 'shared' (1 active user)
>Thread-706::DEBUG::2012-10-15 14:15:25,044::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.e42f70cc-802e-46be-b931-867450cc6282`ReqID=`1ec4c684-5a52-408e-9f56-13702f6d0836`::Granted request
>Thread-706::DEBUG::2012-10-15 14:15:25,045::task::817::TaskManager.Task::(resourceAcquired) Task=`38288ec9-8682-4aa3-be30-a02d53da939b`::_resourcesAcquired: Storage.e42f70cc-802e-46be-b931-867450cc6282 (shared)
>Thread-706::DEBUG::2012-10-15 14:15:25,045::task::978::TaskManager.Task::(_decref) Task=`38288ec9-8682-4aa3-be30-a02d53da939b`::ref 1 aborting False
>Thread-706::INFO::2012-10-15 14:15:25,047::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '3774dc69-8ba3-456e-b584-4c08e3ba3826', 'name': 'DataCenter01', 'version': '3', 'domains': '602b2bde-9a66-4fc3-91ef-8a85894c087c:Attached,3774dc69-8ba3-456e-b584-4c08e3ba3826:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 0}, 'dominfo': {'602b2bde-9a66-4fc3-91ef-8a85894c087c': {'status': 'Attached'}, '3774dc69-8ba3-456e-b584-4c08e3ba3826': {'status': 'Active', 'diskfree': '1041586192384', 'alerts': [], 'disktotal': '1098974756864'}}}
>Thread-706::DEBUG::2012-10-15 14:15:25,048::task::1172::TaskManager.Task::(prepare) Task=`38288ec9-8682-4aa3-be30-a02d53da939b`::finished: {'info': {'spm_id': 1, 'master_uuid': '3774dc69-8ba3-456e-b584-4c08e3ba3826', 'name': 'DataCenter01', 'version': '3', 'domains': '602b2bde-9a66-4fc3-91ef-8a85894c087c:Attached,3774dc69-8ba3-456e-b584-4c08e3ba3826:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 0}, 'dominfo': {'602b2bde-9a66-4fc3-91ef-8a85894c087c': {'status': 'Attached'}, '3774dc69-8ba3-456e-b584-4c08e3ba3826': {'status': 'Active', 'diskfree': '1041586192384', 'alerts': [], 'disktotal': '1098974756864'}}}
>Thread-706::DEBUG::2012-10-15 14:15:25,048::task::588::TaskManager.Task::(_updateState) Task=`38288ec9-8682-4aa3-be30-a02d53da939b`::moving from state preparing -> state finished
>Thread-706::DEBUG::2012-10-15 14:15:25,048::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.e42f70cc-802e-46be-b931-867450cc6282': < ResourceRef 'Storage.e42f70cc-802e-46be-b931-867450cc6282', isValid: 'True' obj: 'None'>}
>Thread-706::DEBUG::2012-10-15 14:15:25,049::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-706::DEBUG::2012-10-15 14:15:25,049::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282'
>Thread-706::DEBUG::2012-10-15 14:15:25,049::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282' (0 active users)
>Thread-706::DEBUG::2012-10-15 14:15:25,050::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282' is free, finding out if anyone is waiting for it.
>Thread-706::DEBUG::2012-10-15 14:15:25,050::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282', Clearing records.
>Thread-706::DEBUG::2012-10-15 14:15:25,050::task::978::TaskManager.Task::(_decref) Task=`38288ec9-8682-4aa3-be30-a02d53da939b`::ref 0 aborting False
>Thread-710::DEBUG::2012-10-15 14:15:31,949::task::588::TaskManager.Task::(_updateState) Task=`d180259e-2a90-4c5c-bb9a-e3eb1b1d5646`::moving from state init -> state preparing
>Thread-710::INFO::2012-10-15 14:15:31,950::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-710::INFO::2012-10-15 14:15:31,950::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'3774dc69-8ba3-456e-b584-4c08e3ba3826': {'delay': '0.0027060508728', 'lastCheck': 1350306930.1321089, 'code': 0, 'valid': True}}
>Thread-710::DEBUG::2012-10-15 14:15:31,950::task::1172::TaskManager.Task::(prepare) Task=`d180259e-2a90-4c5c-bb9a-e3eb1b1d5646`::finished: {'3774dc69-8ba3-456e-b584-4c08e3ba3826': {'delay': '0.0027060508728', 'lastCheck': 1350306930.1321089, 'code': 0, 'valid': True}}
>Thread-710::DEBUG::2012-10-15 14:15:31,950::task::588::TaskManager.Task::(_updateState) Task=`d180259e-2a90-4c5c-bb9a-e3eb1b1d5646`::moving from state preparing -> state finished
>Thread-710::DEBUG::2012-10-15 14:15:31,951::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-710::DEBUG::2012-10-15 14:15:31,951::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-710::DEBUG::2012-10-15 14:15:31,951::task::978::TaskManager.Task::(_decref) Task=`d180259e-2a90-4c5c-bb9a-e3eb1b1d5646`::ref 0 aborting False
>Thread-711::DEBUG::2012-10-15 14:15:31,977::libvirtvm::243::vm.Vm::(_getDiskStats) vmId=`2e915601-b596-4108-9c3b-9d85ecbe1600`::Disk hdc stats not available
>Thread-713::DEBUG::2012-10-15 14:15:35,119::BindingXMLRPC::171::vds::(wrapper) [10.35.70.46]
>Thread-713::DEBUG::2012-10-15 14:15:35,120::task::588::TaskManager.Task::(_updateState) Task=`e9dce0f8-c8cb-494f-9ba3-a85fc4893f8a`::moving from state init -> state preparing
>Thread-713::INFO::2012-10-15 14:15:35,120::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='e42f70cc-802e-46be-b931-867450cc6282', options=None)
>Thread-713::INFO::2012-10-15 14:15:35,120::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 0}}
>Thread-713::DEBUG::2012-10-15 14:15:35,121::task::1172::TaskManager.Task::(prepare) Task=`e9dce0f8-c8cb-494f-9ba3-a85fc4893f8a`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 0}}
>Thread-713::DEBUG::2012-10-15 14:15:35,121::task::588::TaskManager.Task::(_updateState) Task=`e9dce0f8-c8cb-494f-9ba3-a85fc4893f8a`::moving from state preparing -> state finished
>Thread-713::DEBUG::2012-10-15 14:15:35,121::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-713::DEBUG::2012-10-15 14:15:35,121::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-713::DEBUG::2012-10-15 14:15:35,122::task::978::TaskManager.Task::(_decref) Task=`e9dce0f8-c8cb-494f-9ba3-a85fc4893f8a`::ref 0 aborting False
>Thread-714::DEBUG::2012-10-15 14:15:35,141::BindingXMLRPC::171::vds::(wrapper) [10.35.70.46]
>Thread-714::DEBUG::2012-10-15 14:15:35,141::task::588::TaskManager.Task::(_updateState) Task=`54821c0b-ce77-4819-aec6-0b1f46a8d623`::moving from state init -> state preparing
>Thread-714::INFO::2012-10-15 14:15:35,142::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='e42f70cc-802e-46be-b931-867450cc6282', options=None)
>Thread-714::DEBUG::2012-10-15 14:15:35,142::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.e42f70cc-802e-46be-b931-867450cc6282`ReqID=`e977e695-10e1-49dc-8fc4-13575413208e`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-714::DEBUG::2012-10-15 14:15:35,142::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282' for lock type 'shared'
>Thread-714::DEBUG::2012-10-15 14:15:35,143::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282' is free. Now locking as 'shared' (1 active user)
>Thread-714::DEBUG::2012-10-15 14:15:35,143::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.e42f70cc-802e-46be-b931-867450cc6282`ReqID=`e977e695-10e1-49dc-8fc4-13575413208e`::Granted request
>Thread-714::DEBUG::2012-10-15 14:15:35,143::task::817::TaskManager.Task::(resourceAcquired) Task=`54821c0b-ce77-4819-aec6-0b1f46a8d623`::_resourcesAcquired: Storage.e42f70cc-802e-46be-b931-867450cc6282 (shared)
>Thread-714::DEBUG::2012-10-15 14:15:35,144::task::978::TaskManager.Task::(_decref) Task=`54821c0b-ce77-4819-aec6-0b1f46a8d623`::ref 1 aborting False
>Thread-714::INFO::2012-10-15 14:15:35,146::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '3774dc69-8ba3-456e-b584-4c08e3ba3826', 'name': 'DataCenter01', 'version': '3', 'domains': '602b2bde-9a66-4fc3-91ef-8a85894c087c:Attached,3774dc69-8ba3-456e-b584-4c08e3ba3826:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 0}, 'dominfo': {'602b2bde-9a66-4fc3-91ef-8a85894c087c': {'status': 'Attached'}, '3774dc69-8ba3-456e-b584-4c08e3ba3826': {'status': 'Active', 'diskfree': '1041586192384', 'alerts': [], 'disktotal': '1098974756864'}}}
>Thread-714::DEBUG::2012-10-15 14:15:35,146::task::1172::TaskManager.Task::(prepare) Task=`54821c0b-ce77-4819-aec6-0b1f46a8d623`::finished: {'info': {'spm_id': 1, 'master_uuid': '3774dc69-8ba3-456e-b584-4c08e3ba3826', 'name': 'DataCenter01', 'version': '3', 'domains': '602b2bde-9a66-4fc3-91ef-8a85894c087c:Attached,3774dc69-8ba3-456e-b584-4c08e3ba3826:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 0}, 'dominfo': {'602b2bde-9a66-4fc3-91ef-8a85894c087c': {'status': 'Attached'}, '3774dc69-8ba3-456e-b584-4c08e3ba3826': {'status': 'Active', 'diskfree': '1041586192384', 'alerts': [], 'disktotal': '1098974756864'}}}
>Thread-714::DEBUG::2012-10-15 14:15:35,147::task::588::TaskManager.Task::(_updateState) Task=`54821c0b-ce77-4819-aec6-0b1f46a8d623`::moving from state preparing -> state finished
>Thread-714::DEBUG::2012-10-15 14:15:35,147::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.e42f70cc-802e-46be-b931-867450cc6282': < ResourceRef 'Storage.e42f70cc-802e-46be-b931-867450cc6282', isValid: 'True' obj: 'None'>}
>Thread-714::DEBUG::2012-10-15 14:15:35,147::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-714::DEBUG::2012-10-15 14:15:35,147::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282'
>Thread-714::DEBUG::2012-10-15 14:15:35,148::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282' (0 active users)
>Thread-714::DEBUG::2012-10-15 14:15:35,148::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282' is free, finding out if anyone is waiting for it.
>Thread-714::DEBUG::2012-10-15 14:15:35,148::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282', Clearing records.
>Thread-714::DEBUG::2012-10-15 14:15:35,149::task::978::TaskManager.Task::(_decref) Task=`54821c0b-ce77-4819-aec6-0b1f46a8d623`::ref 0 aborting False
>Thread-718::DEBUG::2012-10-15 14:15:42,175::task::588::TaskManager.Task::(_updateState) Task=`a19963aa-0438-4f54-b930-9d8c42d4a6da`::moving from state init -> state preparing
>Thread-718::INFO::2012-10-15 14:15:42,176::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-718::INFO::2012-10-15 14:15:42,176::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'3774dc69-8ba3-456e-b584-4c08e3ba3826': {'delay': '0.00250506401062', 'lastCheck': 1350306940.140177, 'code': 0, 'valid': True}}
>Thread-718::DEBUG::2012-10-15 14:15:42,176::task::1172::TaskManager.Task::(prepare) Task=`a19963aa-0438-4f54-b930-9d8c42d4a6da`::finished: {'3774dc69-8ba3-456e-b584-4c08e3ba3826': {'delay': '0.00250506401062', 'lastCheck': 1350306940.140177, 'code': 0, 'valid': True}}
>Thread-718::DEBUG::2012-10-15 14:15:42,177::task::588::TaskManager.Task::(_updateState) Task=`a19963aa-0438-4f54-b930-9d8c42d4a6da`::moving from state preparing -> state finished
>Thread-718::DEBUG::2012-10-15 14:15:42,177::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-718::DEBUG::2012-10-15 14:15:42,177::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-718::DEBUG::2012-10-15 14:15:42,178::task::978::TaskManager.Task::(_decref) Task=`a19963aa-0438-4f54-b930-9d8c42d4a6da`::ref 0 aborting False
>Thread-719::DEBUG::2012-10-15 14:15:42,201::libvirtvm::243::vm.Vm::(_getDiskStats) vmId=`2e915601-b596-4108-9c3b-9d85ecbe1600`::Disk hdc stats not available
>Thread-721::DEBUG::2012-10-15 14:15:45,220::BindingXMLRPC::171::vds::(wrapper) [10.35.70.46]
>Thread-721::DEBUG::2012-10-15 14:15:45,221::task::588::TaskManager.Task::(_updateState) Task=`6e2e0d67-500f-4fb2-b252-0757da41c1e8`::moving from state init -> state preparing
>Thread-721::INFO::2012-10-15 14:15:45,221::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='e42f70cc-802e-46be-b931-867450cc6282', options=None)
>Thread-721::INFO::2012-10-15 14:15:45,221::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 0}}
>Thread-721::DEBUG::2012-10-15 14:15:45,222::task::1172::TaskManager.Task::(prepare) Task=`6e2e0d67-500f-4fb2-b252-0757da41c1e8`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 0}}
>Thread-721::DEBUG::2012-10-15 14:15:45,222::task::588::TaskManager.Task::(_updateState) Task=`6e2e0d67-500f-4fb2-b252-0757da41c1e8`::moving from state preparing -> state finished
>Thread-721::DEBUG::2012-10-15 14:15:45,222::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-721::DEBUG::2012-10-15 14:15:45,222::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-721::DEBUG::2012-10-15 14:15:45,223::task::978::TaskManager.Task::(_decref) Task=`6e2e0d67-500f-4fb2-b252-0757da41c1e8`::ref 0 aborting False
>Thread-722::DEBUG::2012-10-15 14:15:45,242::BindingXMLRPC::171::vds::(wrapper) [10.35.70.46]
>Thread-722::DEBUG::2012-10-15 14:15:45,243::task::588::TaskManager.Task::(_updateState) Task=`049bd2bc-55ad-49bb-98ad-4e8219369028`::moving from state init -> state preparing
>Thread-722::INFO::2012-10-15 14:15:45,243::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='e42f70cc-802e-46be-b931-867450cc6282', options=None)
>Thread-722::DEBUG::2012-10-15 14:15:45,244::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.e42f70cc-802e-46be-b931-867450cc6282`ReqID=`1573076b-0578-424b-93b9-4fe40e7628bd`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-722::DEBUG::2012-10-15 14:15:45,244::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282' for lock type 'shared'
>Thread-722::DEBUG::2012-10-15 14:15:45,244::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282' is free. Now locking as 'shared' (1 active user)
>Thread-722::DEBUG::2012-10-15 14:15:45,244::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.e42f70cc-802e-46be-b931-867450cc6282`ReqID=`1573076b-0578-424b-93b9-4fe40e7628bd`::Granted request
>Thread-722::DEBUG::2012-10-15 14:15:45,245::task::817::TaskManager.Task::(resourceAcquired) Task=`049bd2bc-55ad-49bb-98ad-4e8219369028`::_resourcesAcquired: Storage.e42f70cc-802e-46be-b931-867450cc6282 (shared)
>Thread-722::DEBUG::2012-10-15 14:15:45,245::task::978::TaskManager.Task::(_decref) Task=`049bd2bc-55ad-49bb-98ad-4e8219369028`::ref 1 aborting False
>Thread-722::INFO::2012-10-15 14:15:45,247::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '3774dc69-8ba3-456e-b584-4c08e3ba3826', 'name': 'DataCenter01', 'version': '3', 'domains': '602b2bde-9a66-4fc3-91ef-8a85894c087c:Attached,3774dc69-8ba3-456e-b584-4c08e3ba3826:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 0}, 'dominfo': {'602b2bde-9a66-4fc3-91ef-8a85894c087c': {'status': 'Attached'}, '3774dc69-8ba3-456e-b584-4c08e3ba3826': {'status': 'Active', 'diskfree': '1041586192384', 'alerts': [], 'disktotal': '1098974756864'}}}
>Thread-722::DEBUG::2012-10-15 14:15:45,248::task::1172::TaskManager.Task::(prepare) Task=`049bd2bc-55ad-49bb-98ad-4e8219369028`::finished: {'info': {'spm_id': 1, 'master_uuid': '3774dc69-8ba3-456e-b584-4c08e3ba3826', 'name': 'DataCenter01', 'version': '3', 'domains': '602b2bde-9a66-4fc3-91ef-8a85894c087c:Attached,3774dc69-8ba3-456e-b584-4c08e3ba3826:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 0}, 'dominfo': {'602b2bde-9a66-4fc3-91ef-8a85894c087c': {'status': 'Attached'}, '3774dc69-8ba3-456e-b584-4c08e3ba3826': {'status': 'Active', 'diskfree': '1041586192384', 'alerts': [], 'disktotal': '1098974756864'}}}
>Thread-722::DEBUG::2012-10-15 14:15:45,248::task::588::TaskManager.Task::(_updateState) Task=`049bd2bc-55ad-49bb-98ad-4e8219369028`::moving from state preparing -> state finished
>Thread-722::DEBUG::2012-10-15 14:15:45,248::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.e42f70cc-802e-46be-b931-867450cc6282': < ResourceRef 'Storage.e42f70cc-802e-46be-b931-867450cc6282', isValid: 'True' obj: 'None'>}
>Thread-722::DEBUG::2012-10-15 14:15:45,249::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-722::DEBUG::2012-10-15 14:15:45,249::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282'
>Thread-722::DEBUG::2012-10-15 14:15:45,249::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282' (0 active users)
>Thread-722::DEBUG::2012-10-15 14:15:45,250::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282' is free, finding out if anyone is waiting for it.
>Thread-722::DEBUG::2012-10-15 14:15:45,250::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282', Clearing records.
>Thread-722::DEBUG::2012-10-15 14:15:45,250::task::978::TaskManager.Task::(_decref) Task=`049bd2bc-55ad-49bb-98ad-4e8219369028`::ref 0 aborting False
>VM Channels Listener::DEBUG::2012-10-15 14:15:45,554::vmChannels::60::vds::(_handle_timeouts) Timeout on fileno 78.
>Thread-595::DEBUG::2012-10-15 14:15:46,718::task::588::TaskManager.Task::(_updateState) Task=`d52150af-925c-436b-a5d5-a7d76725b869`::moving from state init -> state preparing
>Thread-595::INFO::2012-10-15 14:15:46,719::logUtils::37::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='3774dc69-8ba3-456e-b584-4c08e3ba3826', spUUID='e42f70cc-802e-46be-b931-867450cc6282', imgUUID='72387989-9478-428a-842a-ff012b850fa3', volUUID='e8112ab2-4204-49fa-a83e-2b00ff1a57e6', options=None)
>Thread-595::DEBUG::2012-10-15 14:15:46,719::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.3774dc69-8ba3-456e-b584-4c08e3ba3826`ReqID=`f52b380a-3dc6-4773-9864-611f2a4ef5d8`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-595::DEBUG::2012-10-15 14:15:46,719::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.3774dc69-8ba3-456e-b584-4c08e3ba3826' for lock type 'shared'
>Thread-595::DEBUG::2012-10-15 14:15:46,720::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.3774dc69-8ba3-456e-b584-4c08e3ba3826' is free. Now locking as 'shared' (1 active user)
>Thread-595::DEBUG::2012-10-15 14:15:46,720::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.3774dc69-8ba3-456e-b584-4c08e3ba3826`ReqID=`f52b380a-3dc6-4773-9864-611f2a4ef5d8`::Granted request
>Thread-595::DEBUG::2012-10-15 14:15:46,721::task::817::TaskManager.Task::(resourceAcquired) Task=`d52150af-925c-436b-a5d5-a7d76725b869`::_resourcesAcquired: Storage.3774dc69-8ba3-456e-b584-4c08e3ba3826 (shared)
>Thread-595::DEBUG::2012-10-15 14:15:46,721::task::978::TaskManager.Task::(_decref) Task=`d52150af-925c-436b-a5d5-a7d76725b869`::ref 1 aborting False
>Thread-595::DEBUG::2012-10-15 14:15:46,723::fileVolume::552::Storage.Volume::(validateVolumePath) validate path for e8112ab2-4204-49fa-a83e-2b00ff1a57e6
>Thread-595::DEBUG::2012-10-15 14:15:46,727::fileVolume::552::Storage.Volume::(validateVolumePath) validate path for e8112ab2-4204-49fa-a83e-2b00ff1a57e6
>Thread-595::INFO::2012-10-15 14:15:46,729::logUtils::39::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '0', 'apparentsize': '1073741824'}
>Thread-595::DEBUG::2012-10-15 14:15:46,729::task::1172::TaskManager.Task::(prepare) Task=`d52150af-925c-436b-a5d5-a7d76725b869`::finished: {'truesize': '0', 'apparentsize': '1073741824'}
>Thread-595::DEBUG::2012-10-15 14:15:46,729::task::588::TaskManager.Task::(_updateState) Task=`d52150af-925c-436b-a5d5-a7d76725b869`::moving from state preparing -> state finished
>Thread-595::DEBUG::2012-10-15 14:15:46,730::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.3774dc69-8ba3-456e-b584-4c08e3ba3826': < ResourceRef 'Storage.3774dc69-8ba3-456e-b584-4c08e3ba3826', isValid: 'True' obj: 'None'>}
>Thread-595::DEBUG::2012-10-15 14:15:46,730::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-595::DEBUG::2012-10-15 14:15:46,730::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.3774dc69-8ba3-456e-b584-4c08e3ba3826'
>Thread-595::DEBUG::2012-10-15 14:15:46,731::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.3774dc69-8ba3-456e-b584-4c08e3ba3826' (0 active users)
>Thread-595::DEBUG::2012-10-15 14:15:46,731::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.3774dc69-8ba3-456e-b584-4c08e3ba3826' is free, finding out if anyone is waiting for it.
>Thread-595::DEBUG::2012-10-15 14:15:46,731::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.3774dc69-8ba3-456e-b584-4c08e3ba3826', Clearing records.
>Thread-595::DEBUG::2012-10-15 14:15:46,732::task::978::TaskManager.Task::(_decref) Task=`d52150af-925c-436b-a5d5-a7d76725b869`::ref 0 aborting False
>Thread-726::DEBUG::2012-10-15 14:15:52,398::task::588::TaskManager.Task::(_updateState) Task=`76b8ee92-e654-4e71-902f-0ed1d8a39c4a`::moving from state init -> state preparing
>Thread-726::INFO::2012-10-15 14:15:52,399::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-726::INFO::2012-10-15 14:15:52,399::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'3774dc69-8ba3-456e-b584-4c08e3ba3826': {'delay': '0.00265407562256', 'lastCheck': 1350306950.1487319, 'code': 0, 'valid': True}}
>Thread-726::DEBUG::2012-10-15 14:15:52,399::task::1172::TaskManager.Task::(prepare) Task=`76b8ee92-e654-4e71-902f-0ed1d8a39c4a`::finished: {'3774dc69-8ba3-456e-b584-4c08e3ba3826': {'delay': '0.00265407562256', 'lastCheck': 1350306950.1487319, 'code': 0, 'valid': True}}
>Thread-726::DEBUG::2012-10-15 14:15:52,400::task::588::TaskManager.Task::(_updateState) Task=`76b8ee92-e654-4e71-902f-0ed1d8a39c4a`::moving from state preparing -> state finished
>Thread-726::DEBUG::2012-10-15 14:15:52,400::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-726::DEBUG::2012-10-15 14:15:52,400::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-726::DEBUG::2012-10-15 14:15:52,401::task::978::TaskManager.Task::(_decref) Task=`76b8ee92-e654-4e71-902f-0ed1d8a39c4a`::ref 0 aborting False
>Thread-727::DEBUG::2012-10-15 14:15:52,428::libvirtvm::243::vm.Vm::(_getDiskStats) vmId=`2e915601-b596-4108-9c3b-9d85ecbe1600`::Disk hdc stats not available
>Thread-729::DEBUG::2012-10-15 14:15:55,318::BindingXMLRPC::171::vds::(wrapper) [10.35.70.46]
>Thread-729::DEBUG::2012-10-15 14:15:55,318::task::588::TaskManager.Task::(_updateState) Task=`eb4ec41e-89aa-427b-83f0-289587aa30c0`::moving from state init -> state preparing
>Thread-729::INFO::2012-10-15 14:15:55,318::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='e42f70cc-802e-46be-b931-867450cc6282', options=None)
>Thread-729::INFO::2012-10-15 14:15:55,319::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 0}}
>Thread-729::DEBUG::2012-10-15 14:15:55,319::task::1172::TaskManager.Task::(prepare) Task=`eb4ec41e-89aa-427b-83f0-289587aa30c0`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 0}}
>Thread-729::DEBUG::2012-10-15 14:15:55,319::task::588::TaskManager.Task::(_updateState) Task=`eb4ec41e-89aa-427b-83f0-289587aa30c0`::moving from state preparing -> state finished
>Thread-729::DEBUG::2012-10-15 14:15:55,320::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-729::DEBUG::2012-10-15 14:15:55,320::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-729::DEBUG::2012-10-15 14:15:55,320::task::978::TaskManager.Task::(_decref) Task=`eb4ec41e-89aa-427b-83f0-289587aa30c0`::ref 0 aborting False
>Thread-730::DEBUG::2012-10-15 14:15:55,339::BindingXMLRPC::171::vds::(wrapper) [10.35.70.46]
>Thread-730::DEBUG::2012-10-15 14:15:55,339::task::588::TaskManager.Task::(_updateState) Task=`7635c038-5f2d-4188-b363-e878fbc80c30`::moving from state init -> state preparing
>Thread-730::INFO::2012-10-15 14:15:55,340::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='e42f70cc-802e-46be-b931-867450cc6282', options=None)
>Thread-730::DEBUG::2012-10-15 14:15:55,340::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.e42f70cc-802e-46be-b931-867450cc6282`ReqID=`4bda1b5a-bea9-4a3f-a2d8-51a2085cbba5`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-730::DEBUG::2012-10-15 14:15:55,340::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282' for lock type 'shared'
>Thread-730::DEBUG::2012-10-15 14:15:55,341::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282' is free. Now locking as 'shared' (1 active user)
>Thread-730::DEBUG::2012-10-15 14:15:55,341::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.e42f70cc-802e-46be-b931-867450cc6282`ReqID=`4bda1b5a-bea9-4a3f-a2d8-51a2085cbba5`::Granted request
>Thread-730::DEBUG::2012-10-15 14:15:55,341::task::817::TaskManager.Task::(resourceAcquired) Task=`7635c038-5f2d-4188-b363-e878fbc80c30`::_resourcesAcquired: Storage.e42f70cc-802e-46be-b931-867450cc6282 (shared)
>Thread-730::DEBUG::2012-10-15 14:15:55,342::task::978::TaskManager.Task::(_decref) Task=`7635c038-5f2d-4188-b363-e878fbc80c30`::ref 1 aborting False
>Thread-730::INFO::2012-10-15 14:15:55,344::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '3774dc69-8ba3-456e-b584-4c08e3ba3826', 'name': 'DataCenter01', 'version': '3', 'domains': '602b2bde-9a66-4fc3-91ef-8a85894c087c:Attached,3774dc69-8ba3-456e-b584-4c08e3ba3826:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 0}, 'dominfo': {'602b2bde-9a66-4fc3-91ef-8a85894c087c': {'status': 'Attached'}, '3774dc69-8ba3-456e-b584-4c08e3ba3826': {'status': 'Active', 'diskfree': '1041586192384', 'alerts': [], 'disktotal': '1098974756864'}}}
>Thread-730::DEBUG::2012-10-15 14:15:55,344::task::1172::TaskManager.Task::(prepare) Task=`7635c038-5f2d-4188-b363-e878fbc80c30`::finished: {'info': {'spm_id': 1, 'master_uuid': '3774dc69-8ba3-456e-b584-4c08e3ba3826', 'name': 'DataCenter01', 'version': '3', 'domains': '602b2bde-9a66-4fc3-91ef-8a85894c087c:Attached,3774dc69-8ba3-456e-b584-4c08e3ba3826:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 0}, 'dominfo': {'602b2bde-9a66-4fc3-91ef-8a85894c087c': {'status': 'Attached'}, '3774dc69-8ba3-456e-b584-4c08e3ba3826': {'status': 'Active', 'diskfree': '1041586192384', 'alerts': [], 'disktotal': '1098974756864'}}}
>Thread-730::DEBUG::2012-10-15 14:15:55,345::task::588::TaskManager.Task::(_updateState) Task=`7635c038-5f2d-4188-b363-e878fbc80c30`::moving from state preparing -> state finished
>Thread-730::DEBUG::2012-10-15 14:15:55,345::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.e42f70cc-802e-46be-b931-867450cc6282': < ResourceRef 'Storage.e42f70cc-802e-46be-b931-867450cc6282', isValid: 'True' obj: 'None'>}
>Thread-730::DEBUG::2012-10-15 14:15:55,345::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-730::DEBUG::2012-10-15 14:15:55,346::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282'
>Thread-730::DEBUG::2012-10-15 14:15:55,346::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282' (0 active users)
>Thread-730::DEBUG::2012-10-15 14:15:55,346::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282' is free, finding out if anyone is waiting for it.
>Thread-730::DEBUG::2012-10-15 14:15:55,346::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282', Clearing records.
>Thread-730::DEBUG::2012-10-15 14:15:55,347::task::978::TaskManager.Task::(_decref) Task=`7635c038-5f2d-4188-b363-e878fbc80c30`::ref 0 aborting False
>Thread-734::DEBUG::2012-10-15 14:16:02,631::task::588::TaskManager.Task::(_updateState) Task=`f3fb7b5d-ae47-4cbf-90fd-9d936995ae76`::moving from state init -> state preparing
>Thread-734::INFO::2012-10-15 14:16:02,632::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-734::INFO::2012-10-15 14:16:02,632::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'3774dc69-8ba3-456e-b584-4c08e3ba3826': {'delay': '0.00282502174377', 'lastCheck': 1350306960.156951, 'code': 0, 'valid': True}}
>Thread-734::DEBUG::2012-10-15 14:16:02,632::task::1172::TaskManager.Task::(prepare) Task=`f3fb7b5d-ae47-4cbf-90fd-9d936995ae76`::finished: {'3774dc69-8ba3-456e-b584-4c08e3ba3826': {'delay': '0.00282502174377', 'lastCheck': 1350306960.156951, 'code': 0, 'valid': True}}
>Thread-734::DEBUG::2012-10-15 14:16:02,633::task::588::TaskManager.Task::(_updateState) Task=`f3fb7b5d-ae47-4cbf-90fd-9d936995ae76`::moving from state preparing -> state finished
>Thread-734::DEBUG::2012-10-15 14:16:02,633::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-734::DEBUG::2012-10-15 14:16:02,633::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-734::DEBUG::2012-10-15 14:16:02,634::task::978::TaskManager.Task::(_decref) Task=`f3fb7b5d-ae47-4cbf-90fd-9d936995ae76`::ref 0 aborting False
>Thread-735::DEBUG::2012-10-15 14:16:02,661::libvirtvm::243::vm.Vm::(_getDiskStats) vmId=`2e915601-b596-4108-9c3b-9d85ecbe1600`::Disk hdc stats not available
>Thread-737::DEBUG::2012-10-15 14:16:05,422::BindingXMLRPC::171::vds::(wrapper) [10.35.70.46]
>Thread-737::DEBUG::2012-10-15 14:16:05,422::task::588::TaskManager.Task::(_updateState) Task=`5c4a6575-b802-4300-82b1-5bd65fa26472`::moving from state init -> state preparing
>Thread-737::INFO::2012-10-15 14:16:05,423::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='e42f70cc-802e-46be-b931-867450cc6282', options=None)
>Thread-737::INFO::2012-10-15 14:16:05,423::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 0}}
>Thread-737::DEBUG::2012-10-15 14:16:05,423::task::1172::TaskManager.Task::(prepare) Task=`5c4a6575-b802-4300-82b1-5bd65fa26472`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 0}}
>Thread-737::DEBUG::2012-10-15 14:16:05,424::task::588::TaskManager.Task::(_updateState) Task=`5c4a6575-b802-4300-82b1-5bd65fa26472`::moving from state preparing -> state finished
>Thread-737::DEBUG::2012-10-15 14:16:05,424::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-737::DEBUG::2012-10-15 14:16:05,424::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-737::DEBUG::2012-10-15 14:16:05,424::task::978::TaskManager.Task::(_decref) Task=`5c4a6575-b802-4300-82b1-5bd65fa26472`::ref 0 aborting False
>Thread-738::DEBUG::2012-10-15 14:16:05,443::BindingXMLRPC::171::vds::(wrapper) [10.35.70.46]
>Thread-738::DEBUG::2012-10-15 14:16:05,443::task::588::TaskManager.Task::(_updateState) Task=`0b06004c-406f-4a96-b179-085dea5178aa`::moving from state init -> state preparing
>Thread-738::INFO::2012-10-15 14:16:05,443::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='e42f70cc-802e-46be-b931-867450cc6282', options=None)
>Thread-738::DEBUG::2012-10-15 14:16:05,444::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.e42f70cc-802e-46be-b931-867450cc6282`ReqID=`e0fbabbe-d74f-4d08-8d4d-564d3223d172`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-738::DEBUG::2012-10-15 14:16:05,444::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282' for lock type 'shared'
>Thread-738::DEBUG::2012-10-15 14:16:05,444::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282' is free. Now locking as 'shared' (1 active user)
>Thread-738::DEBUG::2012-10-15 14:16:05,445::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.e42f70cc-802e-46be-b931-867450cc6282`ReqID=`e0fbabbe-d74f-4d08-8d4d-564d3223d172`::Granted request
>Thread-738::DEBUG::2012-10-15 14:16:05,445::task::817::TaskManager.Task::(resourceAcquired) Task=`0b06004c-406f-4a96-b179-085dea5178aa`::_resourcesAcquired: Storage.e42f70cc-802e-46be-b931-867450cc6282 (shared)
>Thread-738::DEBUG::2012-10-15 14:16:05,445::task::978::TaskManager.Task::(_decref) Task=`0b06004c-406f-4a96-b179-085dea5178aa`::ref 1 aborting False
>Thread-738::INFO::2012-10-15 14:16:05,448::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '3774dc69-8ba3-456e-b584-4c08e3ba3826', 'name': 'DataCenter01', 'version': '3', 'domains': '602b2bde-9a66-4fc3-91ef-8a85894c087c:Attached,3774dc69-8ba3-456e-b584-4c08e3ba3826:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 0}, 'dominfo': {'602b2bde-9a66-4fc3-91ef-8a85894c087c': {'status': 'Attached'}, '3774dc69-8ba3-456e-b584-4c08e3ba3826': {'status': 'Active', 'diskfree': '1041586192384', 'alerts': [], 'disktotal': '1098974756864'}}}
>Thread-738::DEBUG::2012-10-15 14:16:05,448::task::1172::TaskManager.Task::(prepare) Task=`0b06004c-406f-4a96-b179-085dea5178aa`::finished: {'info': {'spm_id': 1, 'master_uuid': '3774dc69-8ba3-456e-b584-4c08e3ba3826', 'name': 'DataCenter01', 'version': '3', 'domains': '602b2bde-9a66-4fc3-91ef-8a85894c087c:Attached,3774dc69-8ba3-456e-b584-4c08e3ba3826:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 0}, 'dominfo': {'602b2bde-9a66-4fc3-91ef-8a85894c087c': {'status': 'Attached'}, '3774dc69-8ba3-456e-b584-4c08e3ba3826': {'status': 'Active', 'diskfree': '1041586192384', 'alerts': [], 'disktotal': '1098974756864'}}}
>Thread-738::DEBUG::2012-10-15 14:16:05,448::task::588::TaskManager.Task::(_updateState) Task=`0b06004c-406f-4a96-b179-085dea5178aa`::moving from state preparing -> state finished
>Thread-738::DEBUG::2012-10-15 14:16:05,449::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.e42f70cc-802e-46be-b931-867450cc6282': < ResourceRef 'Storage.e42f70cc-802e-46be-b931-867450cc6282', isValid: 'True' obj: 'None'>}
>Thread-738::DEBUG::2012-10-15 14:16:05,449::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-738::DEBUG::2012-10-15 14:16:05,449::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282'
>Thread-738::DEBUG::2012-10-15 14:16:05,450::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282' (0 active users)
>Thread-738::DEBUG::2012-10-15 14:16:05,450::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282' is free, finding out if anyone is waiting for it.
>Thread-738::DEBUG::2012-10-15 14:16:05,450::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282', Clearing records.
>Thread-738::DEBUG::2012-10-15 14:16:05,450::task::978::TaskManager.Task::(_decref) Task=`0b06004c-406f-4a96-b179-085dea5178aa`::ref 0 aborting False
>Thread-742::DEBUG::2012-10-15 14:16:12,866::task::588::TaskManager.Task::(_updateState) Task=`e391303e-6281-4b46-8d2f-12530f41b02d`::moving from state init -> state preparing
>Thread-742::INFO::2012-10-15 14:16:12,866::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-742::INFO::2012-10-15 14:16:12,894::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'3774dc69-8ba3-456e-b584-4c08e3ba3826': {'delay': '0.00287985801697', 'lastCheck': 1350306970.1655481, 'code': 0, 'valid': True}}
>Thread-742::DEBUG::2012-10-15 14:16:12,895::task::1172::TaskManager.Task::(prepare) Task=`e391303e-6281-4b46-8d2f-12530f41b02d`::finished: {'3774dc69-8ba3-456e-b584-4c08e3ba3826': {'delay': '0.00287985801697', 'lastCheck': 1350306970.1655481, 'code': 0, 'valid': True}}
>Thread-742::DEBUG::2012-10-15 14:16:12,895::task::588::TaskManager.Task::(_updateState) Task=`e391303e-6281-4b46-8d2f-12530f41b02d`::moving from state preparing -> state finished
>Thread-742::DEBUG::2012-10-15 14:16:12,895::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-742::DEBUG::2012-10-15 14:16:12,895::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-742::DEBUG::2012-10-15 14:16:12,896::task::978::TaskManager.Task::(_decref) Task=`e391303e-6281-4b46-8d2f-12530f41b02d`::ref 0 aborting False
>Thread-743::DEBUG::2012-10-15 14:16:12,920::libvirtvm::243::vm.Vm::(_getDiskStats) vmId=`2e915601-b596-4108-9c3b-9d85ecbe1600`::Disk hdc stats not available
>Thread-745::DEBUG::2012-10-15 14:16:15,517::BindingXMLRPC::171::vds::(wrapper) [10.35.70.46]
>Thread-745::DEBUG::2012-10-15 14:16:15,517::task::588::TaskManager.Task::(_updateState) Task=`08ec3e0d-360c-4a14-8511-115bc9259abe`::moving from state init -> state preparing
>Thread-745::INFO::2012-10-15 14:16:15,518::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='e42f70cc-802e-46be-b931-867450cc6282', options=None)
>Thread-745::INFO::2012-10-15 14:16:15,518::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 0}}
>Thread-745::DEBUG::2012-10-15 14:16:15,518::task::1172::TaskManager.Task::(prepare) Task=`08ec3e0d-360c-4a14-8511-115bc9259abe`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 0}}
>Thread-745::DEBUG::2012-10-15 14:16:15,519::task::588::TaskManager.Task::(_updateState) Task=`08ec3e0d-360c-4a14-8511-115bc9259abe`::moving from state preparing -> state finished
>Thread-745::DEBUG::2012-10-15 14:16:15,519::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-745::DEBUG::2012-10-15 14:16:15,519::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-745::DEBUG::2012-10-15 14:16:15,519::task::978::TaskManager.Task::(_decref) Task=`08ec3e0d-360c-4a14-8511-115bc9259abe`::ref 0 aborting False
>Thread-746::DEBUG::2012-10-15 14:16:15,538::BindingXMLRPC::171::vds::(wrapper) [10.35.70.46]
>Thread-746::DEBUG::2012-10-15 14:16:15,539::task::588::TaskManager.Task::(_updateState) Task=`69dad013-22d8-4ec7-a611-cdc74ff244f8`::moving from state init -> state preparing
>Thread-746::INFO::2012-10-15 14:16:15,539::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='e42f70cc-802e-46be-b931-867450cc6282', options=None)
>Thread-746::DEBUG::2012-10-15 14:16:15,539::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.e42f70cc-802e-46be-b931-867450cc6282`ReqID=`2b46aa08-ae47-4063-8873-c4242653fbf3`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-746::DEBUG::2012-10-15 14:16:15,540::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282' for lock type 'shared'
>Thread-746::DEBUG::2012-10-15 14:16:15,540::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282' is free. Now locking as 'shared' (1 active user)
>Thread-746::DEBUG::2012-10-15 14:16:15,540::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.e42f70cc-802e-46be-b931-867450cc6282`ReqID=`2b46aa08-ae47-4063-8873-c4242653fbf3`::Granted request
>Thread-746::DEBUG::2012-10-15 14:16:15,541::task::817::TaskManager.Task::(resourceAcquired) Task=`69dad013-22d8-4ec7-a611-cdc74ff244f8`::_resourcesAcquired: Storage.e42f70cc-802e-46be-b931-867450cc6282 (shared)
>Thread-746::DEBUG::2012-10-15 14:16:15,541::task::978::TaskManager.Task::(_decref) Task=`69dad013-22d8-4ec7-a611-cdc74ff244f8`::ref 1 aborting False
>Thread-746::INFO::2012-10-15 14:16:15,543::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '3774dc69-8ba3-456e-b584-4c08e3ba3826', 'name': 'DataCenter01', 'version': '3', 'domains': '602b2bde-9a66-4fc3-91ef-8a85894c087c:Attached,3774dc69-8ba3-456e-b584-4c08e3ba3826:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 0}, 'dominfo': {'602b2bde-9a66-4fc3-91ef-8a85894c087c': {'status': 'Attached'}, '3774dc69-8ba3-456e-b584-4c08e3ba3826': {'status': 'Active', 'diskfree': '1041586192384', 'alerts': [], 'disktotal': '1098974756864'}}}
>Thread-746::DEBUG::2012-10-15 14:16:15,544::task::1172::TaskManager.Task::(prepare) Task=`69dad013-22d8-4ec7-a611-cdc74ff244f8`::finished: {'info': {'spm_id': 1, 'master_uuid': '3774dc69-8ba3-456e-b584-4c08e3ba3826', 'name': 'DataCenter01', 'version': '3', 'domains': '602b2bde-9a66-4fc3-91ef-8a85894c087c:Attached,3774dc69-8ba3-456e-b584-4c08e3ba3826:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 0}, 'dominfo': {'602b2bde-9a66-4fc3-91ef-8a85894c087c': {'status': 'Attached'}, '3774dc69-8ba3-456e-b584-4c08e3ba3826': {'status': 'Active', 'diskfree': '1041586192384', 'alerts': [], 'disktotal': '1098974756864'}}}
>Thread-746::DEBUG::2012-10-15 14:16:15,544::task::588::TaskManager.Task::(_updateState) Task=`69dad013-22d8-4ec7-a611-cdc74ff244f8`::moving from state preparing -> state finished
>Thread-746::DEBUG::2012-10-15 14:16:15,544::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.e42f70cc-802e-46be-b931-867450cc6282': < ResourceRef 'Storage.e42f70cc-802e-46be-b931-867450cc6282', isValid: 'True' obj: 'None'>}
>Thread-746::DEBUG::2012-10-15 14:16:15,544::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-746::DEBUG::2012-10-15 14:16:15,545::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282'
>Thread-746::DEBUG::2012-10-15 14:16:15,545::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282' (0 active users)
>Thread-746::DEBUG::2012-10-15 14:16:15,545::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282' is free, finding out if anyone is waiting for it.
>Thread-746::DEBUG::2012-10-15 14:16:15,546::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282', Clearing records.
>Thread-746::DEBUG::2012-10-15 14:16:15,546::task::978::TaskManager.Task::(_decref) Task=`69dad013-22d8-4ec7-a611-cdc74ff244f8`::ref 0 aborting False
>VM Channels Listener::DEBUG::2012-10-15 14:16:15,590::vmChannels::60::vds::(_handle_timeouts) Timeout on fileno 78.
>Thread-750::DEBUG::2012-10-15 14:16:23,199::task::588::TaskManager.Task::(_updateState) Task=`30f2150f-e7e5-4ead-b0a9-9a3a72e968d4`::moving from state init -> state preparing
>Thread-750::INFO::2012-10-15 14:16:23,200::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-750::INFO::2012-10-15 14:16:23,200::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'3774dc69-8ba3-456e-b584-4c08e3ba3826': {'delay': '0.0155119895935', 'lastCheck': 1350306980.241667, 'code': 0, 'valid': True}}
>Thread-750::DEBUG::2012-10-15 14:16:23,200::task::1172::TaskManager.Task::(prepare) Task=`30f2150f-e7e5-4ead-b0a9-9a3a72e968d4`::finished: {'3774dc69-8ba3-456e-b584-4c08e3ba3826': {'delay': '0.0155119895935', 'lastCheck': 1350306980.241667, 'code': 0, 'valid': True}}
>Thread-750::DEBUG::2012-10-15 14:16:23,201::task::588::TaskManager.Task::(_updateState) Task=`30f2150f-e7e5-4ead-b0a9-9a3a72e968d4`::moving from state preparing -> state finished
>Thread-750::DEBUG::2012-10-15 14:16:23,201::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-750::DEBUG::2012-10-15 14:16:23,201::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-750::DEBUG::2012-10-15 14:16:23,201::task::978::TaskManager.Task::(_decref) Task=`30f2150f-e7e5-4ead-b0a9-9a3a72e968d4`::ref 0 aborting False
>Thread-751::DEBUG::2012-10-15 14:16:23,241::libvirtvm::243::vm.Vm::(_getDiskStats) vmId=`2e915601-b596-4108-9c3b-9d85ecbe1600`::Disk hdc stats not available
>Thread-753::DEBUG::2012-10-15 14:16:25,619::BindingXMLRPC::171::vds::(wrapper) [10.35.70.46]
>Thread-753::DEBUG::2012-10-15 14:16:25,620::task::588::TaskManager.Task::(_updateState) Task=`fbb2f44b-bf04-449e-bbd3-a38a9128d549`::moving from state init -> state preparing
>Thread-753::INFO::2012-10-15 14:16:25,620::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='e42f70cc-802e-46be-b931-867450cc6282', options=None)
>Thread-753::INFO::2012-10-15 14:16:25,620::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 0}}
>Thread-753::DEBUG::2012-10-15 14:16:25,621::task::1172::TaskManager.Task::(prepare) Task=`fbb2f44b-bf04-449e-bbd3-a38a9128d549`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 0}}
>Thread-753::DEBUG::2012-10-15 14:16:25,621::task::588::TaskManager.Task::(_updateState) Task=`fbb2f44b-bf04-449e-bbd3-a38a9128d549`::moving from state preparing -> state finished
>Thread-753::DEBUG::2012-10-15 14:16:25,621::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-753::DEBUG::2012-10-15 14:16:25,621::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-753::DEBUG::2012-10-15 14:16:25,622::task::978::TaskManager.Task::(_decref) Task=`fbb2f44b-bf04-449e-bbd3-a38a9128d549`::ref 0 aborting False
>Thread-754::DEBUG::2012-10-15 14:16:25,641::BindingXMLRPC::171::vds::(wrapper) [10.35.70.46]
>Thread-754::DEBUG::2012-10-15 14:16:25,641::task::588::TaskManager.Task::(_updateState) Task=`397d9910-4485-4b9e-8d4d-2a9774706144`::moving from state init -> state preparing
>Thread-754::INFO::2012-10-15 14:16:25,642::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='e42f70cc-802e-46be-b931-867450cc6282', options=None)
>Thread-754::DEBUG::2012-10-15 14:16:25,642::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.e42f70cc-802e-46be-b931-867450cc6282`ReqID=`62a4888f-26e7-4c10-9c20-12099115546f`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-754::DEBUG::2012-10-15 14:16:25,642::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282' for lock type 'shared'
>Thread-754::DEBUG::2012-10-15 14:16:25,643::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282' is free. Now locking as 'shared' (1 active user)
>Thread-754::DEBUG::2012-10-15 14:16:25,643::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.e42f70cc-802e-46be-b931-867450cc6282`ReqID=`62a4888f-26e7-4c10-9c20-12099115546f`::Granted request
>Thread-754::DEBUG::2012-10-15 14:16:25,644::task::817::TaskManager.Task::(resourceAcquired) Task=`397d9910-4485-4b9e-8d4d-2a9774706144`::_resourcesAcquired: Storage.e42f70cc-802e-46be-b931-867450cc6282 (shared)
>Thread-754::DEBUG::2012-10-15 14:16:25,644::task::978::TaskManager.Task::(_decref) Task=`397d9910-4485-4b9e-8d4d-2a9774706144`::ref 1 aborting False
>Thread-754::INFO::2012-10-15 14:16:25,646::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '3774dc69-8ba3-456e-b584-4c08e3ba3826', 'name': 'DataCenter01', 'version': '3', 'domains': '602b2bde-9a66-4fc3-91ef-8a85894c087c:Attached,3774dc69-8ba3-456e-b584-4c08e3ba3826:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 0}, 'dominfo': {'602b2bde-9a66-4fc3-91ef-8a85894c087c': {'status': 'Attached'}, '3774dc69-8ba3-456e-b584-4c08e3ba3826': {'status': 'Active', 'diskfree': '1041586192384', 'alerts': [], 'disktotal': '1098974756864'}}}
>Thread-754::DEBUG::2012-10-15 14:16:25,646::task::1172::TaskManager.Task::(prepare) Task=`397d9910-4485-4b9e-8d4d-2a9774706144`::finished: {'info': {'spm_id': 1, 'master_uuid': '3774dc69-8ba3-456e-b584-4c08e3ba3826', 'name': 'DataCenter01', 'version': '3', 'domains': '602b2bde-9a66-4fc3-91ef-8a85894c087c:Attached,3774dc69-8ba3-456e-b584-4c08e3ba3826:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 0}, 'dominfo': {'602b2bde-9a66-4fc3-91ef-8a85894c087c': {'status': 'Attached'}, '3774dc69-8ba3-456e-b584-4c08e3ba3826': {'status': 'Active', 'diskfree': '1041586192384', 'alerts': [], 'disktotal': '1098974756864'}}}
>Thread-754::DEBUG::2012-10-15 14:16:25,647::task::588::TaskManager.Task::(_updateState) Task=`397d9910-4485-4b9e-8d4d-2a9774706144`::moving from state preparing -> state finished
>Thread-754::DEBUG::2012-10-15 14:16:25,647::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.e42f70cc-802e-46be-b931-867450cc6282': < ResourceRef 'Storage.e42f70cc-802e-46be-b931-867450cc6282', isValid: 'True' obj: 'None'>}
>Thread-754::DEBUG::2012-10-15 14:16:25,647::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-754::DEBUG::2012-10-15 14:16:25,648::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282'
>Thread-754::DEBUG::2012-10-15 14:16:25,648::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282' (0 active users)
>Thread-754::DEBUG::2012-10-15 14:16:25,648::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282' is free, finding out if anyone is waiting for it.
>Thread-754::DEBUG::2012-10-15 14:16:25,649::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282', Clearing records.
>Thread-754::DEBUG::2012-10-15 14:16:25,649::task::978::TaskManager.Task::(_decref) Task=`397d9910-4485-4b9e-8d4d-2a9774706144`::ref 0 aborting False
>Thread-758::DEBUG::2012-10-15 14:16:33,396::task::588::TaskManager.Task::(_updateState) Task=`63224e66-af20-4349-8b29-727f29ed10a2`::moving from state init -> state preparing
>Thread-758::INFO::2012-10-15 14:16:33,397::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-758::INFO::2012-10-15 14:16:33,397::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'3774dc69-8ba3-456e-b584-4c08e3ba3826': {'delay': '0.00280809402466', 'lastCheck': 1350306990.249855, 'code': 0, 'valid': True}}
>Thread-758::DEBUG::2012-10-15 14:16:33,398::task::1172::TaskManager.Task::(prepare) Task=`63224e66-af20-4349-8b29-727f29ed10a2`::finished: {'3774dc69-8ba3-456e-b584-4c08e3ba3826': {'delay': '0.00280809402466', 'lastCheck': 1350306990.249855, 'code': 0, 'valid': True}}
>Thread-758::DEBUG::2012-10-15 14:16:33,398::task::588::TaskManager.Task::(_updateState) Task=`63224e66-af20-4349-8b29-727f29ed10a2`::moving from state preparing -> state finished
>Thread-758::DEBUG::2012-10-15 14:16:33,398::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-758::DEBUG::2012-10-15 14:16:33,398::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-758::DEBUG::2012-10-15 14:16:33,399::task::978::TaskManager.Task::(_decref) Task=`63224e66-af20-4349-8b29-727f29ed10a2`::ref 0 aborting False
>Thread-759::DEBUG::2012-10-15 14:16:33,421::libvirtvm::243::vm.Vm::(_getDiskStats) vmId=`2e915601-b596-4108-9c3b-9d85ecbe1600`::Disk hdc stats not available
>Thread-761::DEBUG::2012-10-15 14:16:35,726::BindingXMLRPC::171::vds::(wrapper) [10.35.70.46]
>Thread-761::DEBUG::2012-10-15 14:16:35,726::task::588::TaskManager.Task::(_updateState) Task=`17827d2a-af11-473f-bcd1-6b325460bf02`::moving from state init -> state preparing
>Thread-761::INFO::2012-10-15 14:16:35,726::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='e42f70cc-802e-46be-b931-867450cc6282', options=None)
>Thread-761::INFO::2012-10-15 14:16:35,727::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 0}}
>Thread-761::DEBUG::2012-10-15 14:16:35,727::task::1172::TaskManager.Task::(prepare) Task=`17827d2a-af11-473f-bcd1-6b325460bf02`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 0}}
>Thread-761::DEBUG::2012-10-15 14:16:35,727::task::588::TaskManager.Task::(_updateState) Task=`17827d2a-af11-473f-bcd1-6b325460bf02`::moving from state preparing -> state finished
>Thread-761::DEBUG::2012-10-15 14:16:35,728::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-761::DEBUG::2012-10-15 14:16:35,728::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-761::DEBUG::2012-10-15 14:16:35,728::task::978::TaskManager.Task::(_decref) Task=`17827d2a-af11-473f-bcd1-6b325460bf02`::ref 0 aborting False
>Thread-762::DEBUG::2012-10-15 14:16:35,746::BindingXMLRPC::171::vds::(wrapper) [10.35.70.46]
>Thread-762::DEBUG::2012-10-15 14:16:35,746::task::588::TaskManager.Task::(_updateState) Task=`3fbf1169-553b-4346-b043-99496dc9bf13`::moving from state init -> state preparing
>Thread-762::INFO::2012-10-15 14:16:35,747::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='e42f70cc-802e-46be-b931-867450cc6282', options=None)
>Thread-762::DEBUG::2012-10-15 14:16:35,747::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.e42f70cc-802e-46be-b931-867450cc6282`ReqID=`73b5b4a7-8547-454a-b4df-d97bf66704f1`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-762::DEBUG::2012-10-15 14:16:35,747::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282' for lock type 'shared'
>Thread-762::DEBUG::2012-10-15 14:16:35,748::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282' is free. Now locking as 'shared' (1 active user)
>Thread-762::DEBUG::2012-10-15 14:16:35,748::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.e42f70cc-802e-46be-b931-867450cc6282`ReqID=`73b5b4a7-8547-454a-b4df-d97bf66704f1`::Granted request
>Thread-762::DEBUG::2012-10-15 14:16:35,748::task::817::TaskManager.Task::(resourceAcquired) Task=`3fbf1169-553b-4346-b043-99496dc9bf13`::_resourcesAcquired: Storage.e42f70cc-802e-46be-b931-867450cc6282 (shared)
>Thread-762::DEBUG::2012-10-15 14:16:35,749::task::978::TaskManager.Task::(_decref) Task=`3fbf1169-553b-4346-b043-99496dc9bf13`::ref 1 aborting False
>Thread-762::INFO::2012-10-15 14:16:35,751::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '3774dc69-8ba3-456e-b584-4c08e3ba3826', 'name': 'DataCenter01', 'version': '3', 'domains': '602b2bde-9a66-4fc3-91ef-8a85894c087c:Attached,3774dc69-8ba3-456e-b584-4c08e3ba3826:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 0}, 'dominfo': {'602b2bde-9a66-4fc3-91ef-8a85894c087c': {'status': 'Attached'}, '3774dc69-8ba3-456e-b584-4c08e3ba3826': {'status': 'Active', 'diskfree': '1041586192384', 'alerts': [], 'disktotal': '1098974756864'}}}
>Thread-762::DEBUG::2012-10-15 14:16:35,751::task::1172::TaskManager.Task::(prepare) Task=`3fbf1169-553b-4346-b043-99496dc9bf13`::finished: {'info': {'spm_id': 1, 'master_uuid': '3774dc69-8ba3-456e-b584-4c08e3ba3826', 'name': 'DataCenter01', 'version': '3', 'domains': '602b2bde-9a66-4fc3-91ef-8a85894c087c:Attached,3774dc69-8ba3-456e-b584-4c08e3ba3826:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 0}, 'dominfo': {'602b2bde-9a66-4fc3-91ef-8a85894c087c': {'status': 'Attached'}, '3774dc69-8ba3-456e-b584-4c08e3ba3826': {'status': 'Active', 'diskfree': '1041586192384', 'alerts': [], 'disktotal': '1098974756864'}}}
>Thread-762::DEBUG::2012-10-15 14:16:35,752::task::588::TaskManager.Task::(_updateState) Task=`3fbf1169-553b-4346-b043-99496dc9bf13`::moving from state preparing -> state finished
>Thread-762::DEBUG::2012-10-15 14:16:35,752::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.e42f70cc-802e-46be-b931-867450cc6282': < ResourceRef 'Storage.e42f70cc-802e-46be-b931-867450cc6282', isValid: 'True' obj: 'None'>}
>Thread-762::DEBUG::2012-10-15 14:16:35,752::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-762::DEBUG::2012-10-15 14:16:35,753::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282'
>Thread-762::DEBUG::2012-10-15 14:16:35,753::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282' (0 active users)
>Thread-762::DEBUG::2012-10-15 14:16:35,753::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282' is free, finding out if anyone is waiting for it.
>Thread-762::DEBUG::2012-10-15 14:16:35,753::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.e42f70cc-802e-46be-b931-867450cc6282', Clearing records.
>Thread-762::DEBUG::2012-10-15 14:16:35,754::task::978::TaskManager.Task::(_decref) Task=`3fbf1169-553b-4346-b043-99496dc9bf13`::ref 0 aborting False
>Thread-766::DEBUG::2012-10-15 14:16:43,577::task::588::TaskManager.Task::(_updateState) Task=`84ab39d7-bc20-4dc9-8054-d51a968d6034`::moving from state init -> state preparing
>Thread-766::INFO::2012-10-15 14:16:43,577::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-766::INFO::2012-10-15 14:16:43,577::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'3774dc69-8ba3-456e-b584-4c08e3ba3826': {'delay': '0.00286912918091', 'lastCheck': 1350307000.25881, 'code': 0, 'valid': True}}
>Thread-766::DEBUG::2012-10-15 14:16:43,578::task::1172::TaskManager.Task::(prepare) Task=`84ab39d7-bc20-4dc9-8054-d51a968d6034`::finished: {'3774dc69-8ba3-456e-b584-4c08e3ba3826': {'delay': '0.00286912918091', 'lastCheck': 1350307000.25881, 'code': 0, 'valid': True}}
>Thread-766::DEBUG::2012-10-15 14:16:43,578::task::588::TaskManager.Task::(_updateState) Task=`84ab39d7-bc20-4dc9-8054-d51a968d6034`::moving from state preparing -> state finished
>Thread-766::DEBUG::2012-10-15 14:16:43,578::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-766::DEBUG::2012-10-15 14:16:43,579::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-766::DEBUG::2012-10-15 14:16:43,579::task::978::TaskManager.Task::(_decref) Task=`84ab39d7-bc20-4dc9-8054-d51a968d6034`::ref 0 aborting False
>Thread-767::DEBUG::2012-10-15 14:16:43,604::libvirtvm::243::vm.Vm::(_getDiskStats) vmId=`2e915601-b596-4108-9c3b-9d85ecbe1600`::Disk hdc stats not available
>VM Channels Listener::DEBUG::2012-10-15 14:16:45,627::vmChannels::60::vds::(_handle_timeouts) Timeout on fileno 78.
>Thread-769::DEBUG::2012-10-15 14:16:45,798::BindingXMLRPC::171::vds::(wrapper) [10.35.70.46]

Actions: View

Attachments on bug 837003: 627512