Attachment 604544 Details for Bug 848298 – VDSM log

VDSM log

vdsm.log (text/plain), 115.97 KB, created by Allon Mureinik on 2012-08-15 08:16:24 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Allon Mureinik

Created: 2012-08-15 08:16:24 UTC

Size: 115.97 KB

patch

obsolete

>MainThread::INFO::2012-08-15 11:09:44,813::vdsm::71::vds::(run) I am the actual vdsm 4.10-0.239
>MainThread::DEBUG::2012-08-15 11:09:44,951::resourceManager::379::ResourceManager::(registerNamespace) Registering namespace 'Storage'
>MainThread::DEBUG::2012-08-15 11:09:44,952::threadPool::45::Misc.ThreadPool::(__init__) Enter - numThreads: 10.0, waitTimeout: 3, maxTasks: 500.0
>MainThread::DEBUG::2012-08-15 11:09:44,993::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /bin/kill -9 1970' (cwd None)
>MainThread::DEBUG::2012-08-15 11:09:45,009::__init__::1164::Storage.Misc.excCmd::(_log) FAILED: <err> = 'kill 1970: No such process\n'; <rc> = 1
>MainThread::DEBUG::2012-08-15 11:09:45,009::supervdsm::91::SuperVdsmProxy::(_launchSupervdsm) Launching Super Vdsm
>MainThread::DEBUG::2012-08-15 11:09:45,009::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /usr/bin/python /usr/share/vdsm/supervdsmServer.py 5dfed292-a523-4a71-8a4c-e8950c3a4543 4126' (cwd None)
>MainThread::DEBUG::2012-08-15 11:09:45,134::supervdsmServer::306::SuperVdsm.Server::(main) Making sure I'm root
>MainThread::DEBUG::2012-08-15 11:09:45,134::supervdsmServer::310::SuperVdsm.Server::(main) Parsing cmd args
>MainThread::DEBUG::2012-08-15 11:09:45,134::supervdsmServer::313::SuperVdsm.Server::(main) Creating PID file
>MainThread::DEBUG::2012-08-15 11:09:45,134::supervdsmServer::317::SuperVdsm.Server::(main) Cleaning old socket
>MainThread::DEBUG::2012-08-15 11:09:45,134::supervdsmServer::321::SuperVdsm.Server::(main) Setting up keep alive thread
>MainThread::DEBUG::2012-08-15 11:09:45,134::supervdsmServer::327::SuperVdsm.Server::(main) Creating remote object manager
>MainThread::DEBUG::2012-08-15 11:09:45,135::supervdsmServer::338::SuperVdsm.Server::(main) Started serving super vdsm object
>MainThread::DEBUG::2012-08-15 11:09:47,014::supervdsm::113::SuperVdsmProxy::(_connect) Trying to connect to Super Vdsm
>MainThread::DEBUG::2012-08-15 11:09:47,020::supervdsm::84::SuperVdsmProxy::(__init__) Connected to Super Vdsm
>MainThread::DEBUG::2012-08-15 11:09:47,020::multipath::106::Storage.Multipath::(isEnabled) Current revision of multipath.conf detected, preserving
>MainThread::DEBUG::2012-08-15 11:09:47,021::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/lvm dumpconfig global/locking_type' (cwd None)
>MainThread::DEBUG::2012-08-15 11:09:47,104::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
>MainThread::DEBUG::2012-08-15 11:09:47,104::lvm::334::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' got the operation mutex
>MainThread::DEBUG::2012-08-15 11:09:47,105::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/lvm pvs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 filter = [ \\"r%.*%\\" ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1 }  backup {  retain_min = 50  retain_days = 0 } " --noheadings --units b --nosuffix --separator | -o uuid,name,size,vg_name,vg_uuid,pe_start,pe_count,pe_alloc_count,mda_count,dev_size' (cwd None)
>MainThread::DEBUG::2012-08-15 11:09:47,184::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
>MainThread::DEBUG::2012-08-15 11:09:47,184::lvm::359::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' released the operation mutex
>MainThread::DEBUG::2012-08-15 11:09:47,184::lvm::368::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>MainThread::DEBUG::2012-08-15 11:09:47,185::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/lvm vgs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 filter = [ \\"r%.*%\\" ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1 }  backup {  retain_min = 50  retain_days = 0 } " --noheadings --units b --nosuffix --separator | -o uuid,name,attr,size,free,extent_size,extent_count,free_count,tags,vg_mda_size,vg_mda_free' (cwd None)
>MainThread::DEBUG::2012-08-15 11:09:47,256::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
>MainThread::DEBUG::2012-08-15 11:09:47,256::lvm::397::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>MainThread::DEBUG::2012-08-15 11:09:47,256::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/lvm lvs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 filter = [ \\"r%.*%\\" ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1 }  backup {  retain_min = 50  retain_days = 0 } " --noheadings --units b --nosuffix --separator | -o uuid,name,vg_name,attr,size,seg_start_pe,devices,tags' (cwd None)
>MainThread::DEBUG::2012-08-15 11:09:47,327::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
>Thread-12::DEBUG::2012-08-15 11:09:47,328::misc::1061::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>MainThread::INFO::2012-08-15 11:09:47,328::dispatcher::95::Storage.Dispatcher::(__init__) Starting StorageDispatcher...
>Thread-12::DEBUG::2012-08-15 11:09:47,329::misc::1063::SamplingMethod::(__call__) Got in to sampling method
>Thread-12::DEBUG::2012-08-15 11:09:47,329::misc::1061::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>Thread-12::DEBUG::2012-08-15 11:09:47,329::misc::1063::SamplingMethod::(__call__) Got in to sampling method
>Thread-12::DEBUG::2012-08-15 11:09:47,330::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
>MainThread::DEBUG::2012-08-15 11:09:47,336::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/pgrep -xf ksmd' (cwd None)
>Thread-12::DEBUG::2012-08-15 11:09:47,340::__init__::1164::Storage.Misc.excCmd::(_log) FAILED: <err> = 'iscsiadm: No session found.\n'; <rc> = 21
>Thread-12::DEBUG::2012-08-15 11:09:47,340::misc::1071::SamplingMethod::(__call__) Returning last result
>MainThread::DEBUG::2012-08-15 11:09:47,355::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
>MainThread::INFO::2012-08-15 11:09:47,356::vmChannels::139::vds::(settimeout) Setting channels' timeout to 30 seconds.
>VM Channels Listener::INFO::2012-08-15 11:09:47,356::vmChannels::127::vds::(run) Starting VM channels listener thread.
>MainThread::WARNING::2012-08-15 11:09:47,362::clientIF::169::vds::(_prepareBindings) Unable to load the rest server module. Please make sure it is installed.
>Thread-12::DEBUG::2012-08-15 11:09:47,972::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/multipath' (cwd None)
>Thread-12::DEBUG::2012-08-15 11:09:48,046::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
>Thread-12::DEBUG::2012-08-15 11:09:48,046::lvm::477::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-12::DEBUG::2012-08-15 11:09:48,047::lvm::479::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-12::DEBUG::2012-08-15 11:09:48,047::lvm::488::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-12::DEBUG::2012-08-15 11:09:48,047::lvm::490::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-12::DEBUG::2012-08-15 11:09:48,047::lvm::508::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-12::DEBUG::2012-08-15 11:09:48,047::lvm::510::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-12::DEBUG::2012-08-15 11:09:48,047::misc::1071::SamplingMethod::(__call__) Returning last result
>Thread-12::DEBUG::2012-08-15 11:09:48,048::hsm::355::Storage.HSM::(__cleanStorageRepository) Started cleaning storage repository at '/rhev/data-center'
>Thread-12::DEBUG::2012-08-15 11:09:48,051::hsm::387::Storage.HSM::(__cleanStorageRepository) White list: ['/rhev/data-center/hsm-tasks', '/rhev/data-center/hsm-tasks/*', '/rhev/data-center/mnt']
>Thread-12::DEBUG::2012-08-15 11:09:48,051::hsm::388::Storage.HSM::(__cleanStorageRepository) Mount list: ['/rhev/data-center/mnt/multipass.eng.lab.tlv.redhat.com:_export_images_rnd_amureini_posix1', '/rhev/data-center/mnt/multipass.eng.lab.tlv.redhat.com:_export_images_rnd_amureini_data1', '/rhev/data-center/mnt/multipass.eng.lab.tlv.redhat.com:_export_images_rnd_amureini_data2']
>Thread-12::DEBUG::2012-08-15 11:09:48,051::hsm::390::Storage.HSM::(__cleanStorageRepository) Cleaning leftovers
>Thread-12::DEBUG::2012-08-15 11:09:48,053::hsm::433::Storage.HSM::(__cleanStorageRepository) Finished cleaning storage repository at '/rhev/data-center'
>Thread-12::DEBUG::2012-08-15 11:09:48,054::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1`ReqID=`48efb60a-666b-4a8b-a3fc-234f0cbff83e`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-12::DEBUG::2012-08-15 11:09:48,054::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1' for lock type 'exclusive'
>Thread-12::DEBUG::2012-08-15 11:09:48,054::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1' is free. Now locking as 'exclusive' (1 active user)
>Thread-12::DEBUG::2012-08-15 11:09:48,054::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1`ReqID=`48efb60a-666b-4a8b-a3fc-234f0cbff83e`::Granted request
>Thread-12::INFO::2012-08-15 11:09:48,054::sp::622::Storage.StoragePool::(connect) Connect host #1 to the storage pool 22f91e5e-fa21-4975-8fac-f6ab5191cab1 with master domain: a074f327-d0d2-445a-af76-60a5c69fbc29 (ver = 1)
>Thread-12::DEBUG::2012-08-15 11:09:48,054::lvm::477::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-12::DEBUG::2012-08-15 11:09:48,055::lvm::479::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-12::DEBUG::2012-08-15 11:09:48,055::lvm::488::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-12::DEBUG::2012-08-15 11:09:48,055::lvm::490::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-12::DEBUG::2012-08-15 11:09:48,055::lvm::508::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-12::DEBUG::2012-08-15 11:09:48,055::lvm::510::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-12::DEBUG::2012-08-15 11:09:48,055::misc::1061::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>Thread-12::DEBUG::2012-08-15 11:09:48,055::misc::1063::SamplingMethod::(__call__) Got in to sampling method
>Thread-12::DEBUG::2012-08-15 11:09:48,055::misc::1061::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>Thread-12::DEBUG::2012-08-15 11:09:48,055::misc::1063::SamplingMethod::(__call__) Got in to sampling method
>Thread-12::DEBUG::2012-08-15 11:09:48,056::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
>Thread-12::DEBUG::2012-08-15 11:09:48,067::__init__::1164::Storage.Misc.excCmd::(_log) FAILED: <err> = 'iscsiadm: No session found.\n'; <rc> = 21
>Thread-12::DEBUG::2012-08-15 11:09:48,067::misc::1071::SamplingMethod::(__call__) Returning last result
>Thread-12::DEBUG::2012-08-15 11:09:48,698::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/multipath' (cwd None)
>Thread-12::DEBUG::2012-08-15 11:09:48,741::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
>Thread-12::DEBUG::2012-08-15 11:09:48,741::lvm::477::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-12::DEBUG::2012-08-15 11:09:48,742::lvm::479::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-12::DEBUG::2012-08-15 11:09:48,742::lvm::488::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-12::DEBUG::2012-08-15 11:09:48,742::lvm::490::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-12::DEBUG::2012-08-15 11:09:48,742::lvm::508::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-12::DEBUG::2012-08-15 11:09:48,742::lvm::510::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-12::DEBUG::2012-08-15 11:09:48,742::misc::1071::SamplingMethod::(__call__) Returning last result
>Thread-12::DEBUG::2012-08-15 11:09:48,743::lvm::368::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>Thread-12::DEBUG::2012-08-15 11:09:48,743::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/lvm vgs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 filter = [ \\"r%.*%\\" ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1 }  backup {  retain_min = 50  retain_days = 0 } " --noheadings --units b --nosuffix --separator | -o uuid,name,attr,size,free,extent_size,extent_count,free_count,tags,vg_mda_size,vg_mda_free a074f327-d0d2-445a-af76-60a5c69fbc29' (cwd None)
>Thread-12::DEBUG::2012-08-15 11:09:48,823::__init__::1164::Storage.Misc.excCmd::(_log) FAILED: <err> = '  Volume group "a074f327-d0d2-445a-af76-60a5c69fbc29" not found\n'; <rc> = 5
>Thread-12::WARNING::2012-08-15 11:09:48,824::lvm::373::Storage.LVM::(_reloadvgs) lvm vgs failed: 5 [] ['  Volume group "a074f327-d0d2-445a-af76-60a5c69fbc29" not found']
>Thread-12::DEBUG::2012-08-15 11:09:48,824::lvm::397::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>Thread-12::DEBUG::2012-08-15 11:09:48,930::fileSD::107::Storage.StorageDomain::(__init__) Reading domain in path /rhev/data-center/mnt/multipass.eng.lab.tlv.redhat.com:_export_images_rnd_amureini_data2/a074f327-d0d2-445a-af76-60a5c69fbc29
>Thread-12::DEBUG::2012-08-15 11:09:48,930::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with FileMetadataRW backend
>Thread-12::DEBUG::2012-08-15 11:09:48,967::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=s2', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=dc2', 'POOL_DOMAINS=a074f327-d0d2-445a-af76-60a5c69fbc29:Active', 'POOL_SPM_ID=1', 'POOL_SPM_LVER=0', 'POOL_UUID=22f91e5e-fa21-4975-8fac-f6ab5191cab1', 'REMOTE_PATH=multipass.eng.lab.tlv.redhat.com:/export/images/rnd/amureini/data2', 'ROLE=Master', 'SDUUID=a074f327-d0d2-445a-af76-60a5c69fbc29', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=22ced00ae474ba3908384a3f705d9af307d93104']
>Thread-12::DEBUG::2012-08-15 11:09:48,998::fileSD::419::Storage.StorageDomain::(imageGarbageCollector) Removing remnants of deleted images []
>Thread-12::DEBUG::2012-08-15 11:09:48,998::resourceManager::379::ResourceManager::(registerNamespace) Registering namespace 'a074f327-d0d2-445a-af76-60a5c69fbc29_imageNS'
>Thread-12::DEBUG::2012-08-15 11:09:48,999::resourceManager::379::ResourceManager::(registerNamespace) Registering namespace 'a074f327-d0d2-445a-af76-60a5c69fbc29_volumeNS'
>Thread-12::DEBUG::2012-08-15 11:09:48,999::sp::1519::Storage.StoragePool::(getMasterDomain) Master domain a074f327-d0d2-445a-af76-60a5c69fbc29 verified, version 1
>Thread-12::DEBUG::2012-08-15 11:09:48,999::misc::1061::SamplingMethod::(__call__) Trying to enter sampling method (storage.sp.updateMonitoringThreads)
>Thread-12::DEBUG::2012-08-15 11:09:48,999::misc::1063::SamplingMethod::(__call__) Got in to sampling method
>Thread-12::DEBUG::2012-08-15 11:09:49,005::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=s2', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=dc2', 'POOL_DOMAINS=a074f327-d0d2-445a-af76-60a5c69fbc29:Active', 'POOL_SPM_ID=1', 'POOL_SPM_LVER=0', 'POOL_UUID=22f91e5e-fa21-4975-8fac-f6ab5191cab1', 'REMOTE_PATH=multipass.eng.lab.tlv.redhat.com:/export/images/rnd/amureini/data2', 'ROLE=Master', 'SDUUID=a074f327-d0d2-445a-af76-60a5c69fbc29', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=22ced00ae474ba3908384a3f705d9af307d93104']
>Thread-12::DEBUG::2012-08-15 11:09:49,006::sp::1554::Storage.StoragePool::(updateMonitoringThreads) Storage Pool `22f91e5e-fa21-4975-8fac-f6ab5191cab1` started monitoring domain `a074f327-d0d2-445a-af76-60a5c69fbc29`
>Thread-12::DEBUG::2012-08-15 11:09:49,006::misc::1071::SamplingMethod::(__call__) Returning last result
>Thread-12::DEBUG::2012-08-15 11:09:49,007::lvm::368::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>Thread-12::DEBUG::2012-08-15 11:09:49,008::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/lvm vgs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 filter = [ \\"r%.*%\\" ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1 }  backup {  retain_min = 50  retain_days = 0 } " --noheadings --units b --nosuffix --separator | -o uuid,name,attr,size,free,extent_size,extent_count,free_count,tags,vg_mda_size,vg_mda_free' (cwd None)
>Thread-12::DEBUG::2012-08-15 11:09:49,078::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
>Thread-12::DEBUG::2012-08-15 11:09:49,078::lvm::397::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>Thread-12::INFO::2012-08-15 11:09:49,089::sp::1118::Storage.StoragePool::(_linkStorageDomain) Linking /rhev/data-center/mnt/multipass.eng.lab.tlv.redhat.com:_export_images_rnd_amureini_data2/a074f327-d0d2-445a-af76-60a5c69fbc29 to /rhev/data-center/22f91e5e-fa21-4975-8fac-f6ab5191cab1/a074f327-d0d2-445a-af76-60a5c69fbc29
>Thread-12::INFO::2012-08-15 11:09:49,090::sp::1118::Storage.StoragePool::(_linkStorageDomain) Linking /rhev/data-center/mnt/multipass.eng.lab.tlv.redhat.com:_export_images_rnd_amureini_data2/a074f327-d0d2-445a-af76-60a5c69fbc29 to /rhev/data-center/22f91e5e-fa21-4975-8fac-f6ab5191cab1/mastersd
>Thread-12::DEBUG::2012-08-15 11:09:49,090::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1'
>Thread-12::DEBUG::2012-08-15 11:09:49,090::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1' (0 active users)
>Thread-12::DEBUG::2012-08-15 11:09:49,090::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1' is free, finding out if anyone is waiting for it.
>Thread-12::DEBUG::2012-08-15 11:09:49,091::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1', Clearing records.
>Thread-60::DEBUG::2012-08-15 11:10:15,640::task::568::TaskManager.Task::(_updateState) Task=`3bfdafd8-8d12-40ba-b5e9-c2c1883cb9f5`::moving from state init -> state preparing
>Thread-60::INFO::2012-08-15 11:10:15,643::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-60::INFO::2012-08-15 11:10:15,643::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'a074f327-d0d2-445a-af76-60a5c69fbc29': {'delay': '0.007239818573', 'lastCheck': 1345018209.0471039, 'code': 0, 'valid': True}}
>Thread-60::DEBUG::2012-08-15 11:10:15,643::task::1151::TaskManager.Task::(prepare) Task=`3bfdafd8-8d12-40ba-b5e9-c2c1883cb9f5`::finished: {'a074f327-d0d2-445a-af76-60a5c69fbc29': {'delay': '0.007239818573', 'lastCheck': 1345018209.0471039, 'code': 0, 'valid': True}}
>Thread-60::DEBUG::2012-08-15 11:10:15,644::task::568::TaskManager.Task::(_updateState) Task=`3bfdafd8-8d12-40ba-b5e9-c2c1883cb9f5`::moving from state preparing -> state finished
>Thread-60::DEBUG::2012-08-15 11:10:15,644::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-60::DEBUG::2012-08-15 11:10:15,644::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-60::DEBUG::2012-08-15 11:10:15,644::task::957::TaskManager.Task::(_decref) Task=`3bfdafd8-8d12-40ba-b5e9-c2c1883cb9f5`::ref 0 aborting False
>Thread-61::DEBUG::2012-08-15 11:10:15,717::BindingXMLRPC::872::vds::(wrapper) client [10.35.1.234]::call getCapabilities with () {}
>Thread-61::DEBUG::2012-08-15 11:10:15,814::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" qemu-kvm' (cwd None)
>Thread-61::DEBUG::2012-08-15 11:10:15,827::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
>Thread-61::DEBUG::2012-08-15 11:10:15,828::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" qemu-img' (cwd None)
>Thread-61::DEBUG::2012-08-15 11:10:15,841::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
>Thread-61::DEBUG::2012-08-15 11:10:15,841::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" vdsm' (cwd None)
>Thread-61::DEBUG::2012-08-15 11:10:15,853::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
>Thread-61::DEBUG::2012-08-15 11:10:15,853::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" spice-server' (cwd None)
>Thread-61::DEBUG::2012-08-15 11:10:15,865::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
>Thread-61::DEBUG::2012-08-15 11:10:15,865::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" libvirt' (cwd None)
>Thread-61::DEBUG::2012-08-15 11:10:15,878::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
>Thread-61::DEBUG::2012-08-15 11:10:16,087::BindingXMLRPC::879::vds::(wrapper) return getCapabilities with {'status': {'message': 'Done', 'code': 0}, 'info': {'HBAInventory': {'iSCSI': [{'InitiatorName': 'iqn.1994-05.com.redhat:27c1ec9f7eff'}], 'FC': []}, 'packages2': {'kernel': {'release': '279.2.1.el6.x86_64', 'buildtime': 1341511738.0, 'version': '2.6.32'}, 'spice-server': {'release': '5.el6', 'buildtime': '1333631639', 'version': '0.10.1'}, 'vdsm': {'release': '0.239.gitf693264.el6', 'buildtime': '1343813065', 'version': '4.10.0'}, 'qemu-kvm': {'release': '2.295.el6_3.1', 'buildtime': '1342464920', 'version': '0.12.1.2'}, 'libvirt': {'release': '21.el6', 'buildtime': '1337779106', 'version': '0.9.10'}, 'qemu-img': {'release': '2.295.el6_3.1', 'buildtime': '1342464920', 'version': '0.12.1.2'}}, 'cpuModel': 'Intel(R) Core(TM) i7-2600 CPU @ 3.40GHz', 'hooks': {}, 'vmTypes': ['kvm'], 'supportedProtocols': ['2.2', '2.3'], 'networks': {'engine': {'addr': '', 'cfg': {'DEVICE': 'engine', 'DELAY': '0', 'TYPE': 'Bridge', 'ONBOOT': 'yes', 'STP': 'no'}, 'mtu': '1500', 'netmask': '', 'stp': 'off', 'bridged': True, 'interface': 'engine', 'gateway': '0.0.0.0', 'ports': []}, 'ovirtmgmt': {'addr': '10.35.1.62', 'cfg': {'DELAY': '0', 'BOOTPROTO': 'dhcp', 'STP': 'no', 'DEVICE': 'ovirtmgmt', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '255.255.254.0', 'stp': 'off', 'bridged': True, 'interface': 'ovirtmgmt', 'gateway': '10.35.1.254', 'ports': ['em1']}}, 'bridges': {'ovirtmgmt': {'addr': '10.35.1.62', 'cfg': {'DELAY': '0', 'BOOTPROTO': 'dhcp', 'STP': 'no', 'DEVICE': 'ovirtmgmt', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '255.255.254.0', 'stp': 'off', 'ports': ['em1']}, 'engine': {'addr': '', 'cfg': {'DEVICE': 'engine', 'DELAY': '0', 'TYPE': 'Bridge', 'ONBOOT': 'yes', 'STP': 'no'}, 'mtu': '1500', 'netmask': '', 'stp': 'off', 'ports': []}}, 'uuid': '4C4C4544-0043-5010-8038-CAC04F37354A_18:03:73:cb:c1:ce', 'lastClientIface': 'ovirtmgmt', 'nics': {'em1': {'addr': '', 'cfg': {'DEVICE': 'em1', 'HWADDR': '18:03:73:CB:C1:CE', 'BOOTPROTO': 'none', 'ONBOOT': 'yes', 'BRIDGE': 'ovirtmgmt'}, 'mtu': '1500', 'netmask': '', 'hwaddr': '18:03:73:cb:c1:ce', 'speed': 1000}}, 'software_revision': '0.239', 'management_ip': '', 'clusterLevels': ['3.0', '3.1'], 'cpuFlags': u'fpu,vme,de,pse,tsc,msr,pae,mce,cx8,apic,mtrr,pge,mca,cmov,pat,pse36,clflush,dts,acpi,mmx,fxsr,sse,sse2,ss,ht,tm,pbe,syscall,nx,rdtscp,lm,constant_tsc,arch_perfmon,pebs,bts,rep_good,xtopology,nonstop_tsc,aperfmperf,pni,pclmulqdq,dtes64,monitor,ds_cpl,vmx,smx,est,tm2,ssse3,cx16,xtpr,pdcm,sse4_1,sse4_2,x2apic,popcnt,aes,xsave,avx,lahf_lm,ida,arat,epb,xsaveopt,pln,pts,dts,tpr_shadow,vnmi,flexpriority,ept,vpid,model_Nehalem,model_Conroe,model_Penryn,model_Westmere,model_SandyBridge', 'ISCSIInitiatorName': 'iqn.1994-05.com.redhat:27c1ec9f7eff', 'netConfigDirty': 'False', 'memSize': '7750', 'reservedMem': '321', 'bondings': {'bond4': {'addr': '', 'cfg': {}, 'mtu': '1500', 'netmask': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00'}, 'bond0': {'addr': '', 'cfg': {}, 'mtu': '1500', 'netmask': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00'}, 'bond1': {'addr': '', 'cfg': {}, 'mtu': '1500', 'netmask': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00'}, 'bond2': {'addr': '', 'cfg': {}, 'mtu': '1500', 'netmask': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00'}, 'bond3': {'addr': '', 'cfg': {}, 'mtu': '1500', 'netmask': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00'}}, 'software_version': '4.10', 'cpuSpeed': '1600.000', 'cpuSockets': '1', 'vlans': {}, 'cpuCores': '4', 'kvmEnabled': 'true', 'guestOverhead': '65', 'supportedRHEVMs': ['3.0', '3.1'], 'version_name': 'Snow Man', 'emulatedMachines': [u'rhel6.3.0', u'pc', u'rhel6.2.0', u'rhel6.1.0', u'rhel6.0.0', u'rhel5.5.0', u'rhel5.4.4', u'rhel5.4.0'], 'operatingSystem': {'release': '6.3.0.2.el6', 'version': '6Server', 'name': 'RHEL'}, 'lastClient': '10.35.1.234'}}
>Thread-66::DEBUG::2012-08-15 11:10:23,657::BindingXMLRPC::160::vds::(wrapper) [10.35.1.234]
>Thread-66::DEBUG::2012-08-15 11:10:23,657::task::568::TaskManager.Task::(_updateState) Task=`6eb7f512-45c0-4f2a-9245-8cebfd074124`::moving from state init -> state preparing
>Thread-66::INFO::2012-08-15 11:10:23,657::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='22f91e5e-fa21-4975-8fac-f6ab5191cab1', options=None)
>Thread-66::DEBUG::2012-08-15 11:10:23,665::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=s2', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=dc2', 'POOL_DOMAINS=a074f327-d0d2-445a-af76-60a5c69fbc29:Active', 'POOL_SPM_ID=1', 'POOL_SPM_LVER=0', 'POOL_UUID=22f91e5e-fa21-4975-8fac-f6ab5191cab1', 'REMOTE_PATH=multipass.eng.lab.tlv.redhat.com:/export/images/rnd/amureini/data2', 'ROLE=Master', 'SDUUID=a074f327-d0d2-445a-af76-60a5c69fbc29', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=22ced00ae474ba3908384a3f705d9af307d93104']
>Thread-66::INFO::2012-08-15 11:10:23,666::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 0}}
>Thread-66::DEBUG::2012-08-15 11:10:23,666::task::1151::TaskManager.Task::(prepare) Task=`6eb7f512-45c0-4f2a-9245-8cebfd074124`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 0}}
>Thread-66::DEBUG::2012-08-15 11:10:23,666::task::568::TaskManager.Task::(_updateState) Task=`6eb7f512-45c0-4f2a-9245-8cebfd074124`::moving from state preparing -> state finished
>Thread-66::DEBUG::2012-08-15 11:10:23,666::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-66::DEBUG::2012-08-15 11:10:23,666::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-66::DEBUG::2012-08-15 11:10:23,666::task::957::TaskManager.Task::(_decref) Task=`6eb7f512-45c0-4f2a-9245-8cebfd074124`::ref 0 aborting False
>Thread-67::DEBUG::2012-08-15 11:10:23,672::BindingXMLRPC::160::vds::(wrapper) [10.35.1.234]
>Thread-67::DEBUG::2012-08-15 11:10:23,673::task::568::TaskManager.Task::(_updateState) Task=`83c11b07-91ea-4e08-9c2d-33b29d5c98f0`::moving from state init -> state preparing
>Thread-67::INFO::2012-08-15 11:10:23,673::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='22f91e5e-fa21-4975-8fac-f6ab5191cab1', options=None)
>Thread-67::DEBUG::2012-08-15 11:10:23,679::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=s2', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=dc2', 'POOL_DOMAINS=a074f327-d0d2-445a-af76-60a5c69fbc29:Active', 'POOL_SPM_ID=1', 'POOL_SPM_LVER=0', 'POOL_UUID=22f91e5e-fa21-4975-8fac-f6ab5191cab1', 'REMOTE_PATH=multipass.eng.lab.tlv.redhat.com:/export/images/rnd/amureini/data2', 'ROLE=Master', 'SDUUID=a074f327-d0d2-445a-af76-60a5c69fbc29', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=22ced00ae474ba3908384a3f705d9af307d93104']
>Thread-67::INFO::2012-08-15 11:10:23,680::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 0}}
>Thread-67::DEBUG::2012-08-15 11:10:23,680::task::1151::TaskManager.Task::(prepare) Task=`83c11b07-91ea-4e08-9c2d-33b29d5c98f0`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 0}}
>Thread-67::DEBUG::2012-08-15 11:10:23,680::task::568::TaskManager.Task::(_updateState) Task=`83c11b07-91ea-4e08-9c2d-33b29d5c98f0`::moving from state preparing -> state finished
>Thread-67::DEBUG::2012-08-15 11:10:23,680::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-67::DEBUG::2012-08-15 11:10:23,680::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-67::DEBUG::2012-08-15 11:10:23,680::task::957::TaskManager.Task::(_decref) Task=`83c11b07-91ea-4e08-9c2d-33b29d5c98f0`::ref 0 aborting False
>Thread-68::DEBUG::2012-08-15 11:10:23,715::BindingXMLRPC::160::vds::(wrapper) [10.35.1.234]
>Thread-68::DEBUG::2012-08-15 11:10:23,715::task::568::TaskManager.Task::(_updateState) Task=`1633319d-222b-41d0-808c-55ac47143904`::moving from state init -> state preparing
>Thread-68::INFO::2012-08-15 11:10:23,715::logUtils::37::dispatcher::(wrapper) Run and protect: spmStart(spUUID='22f91e5e-fa21-4975-8fac-f6ab5191cab1', prevID=1, prevLVER='0', recoveryMode=None, scsiFencing='false', maxHostID=250, domVersion='3', options=None)
>Thread-68::DEBUG::2012-08-15 11:10:23,716::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1`ReqID=`7dff9584-7636-4260-a0bb-18c5f7a785f3`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-68::DEBUG::2012-08-15 11:10:23,716::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1' for lock type 'exclusive'
>Thread-68::DEBUG::2012-08-15 11:10:23,716::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1' is free. Now locking as 'exclusive' (1 active user)
>Thread-68::DEBUG::2012-08-15 11:10:23,716::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1`ReqID=`7dff9584-7636-4260-a0bb-18c5f7a785f3`::Granted request
>Thread-68::DEBUG::2012-08-15 11:10:23,716::task::794::TaskManager.Task::(resourceAcquired) Task=`1633319d-222b-41d0-808c-55ac47143904`::_resourcesAcquired: Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1 (exclusive)
>Thread-68::DEBUG::2012-08-15 11:10:23,716::task::957::TaskManager.Task::(_decref) Task=`1633319d-222b-41d0-808c-55ac47143904`::ref 1 aborting False
>Thread-68::INFO::2012-08-15 11:10:23,717::logUtils::39::dispatcher::(wrapper) Run and protect: spmStart, Return response: None
>Thread-68::DEBUG::2012-08-15 11:10:23,717::task::1146::TaskManager.Task::(prepare) Task=`1633319d-222b-41d0-808c-55ac47143904`::Prepare: 1 jobs exist, move to acquiring
>Thread-68::DEBUG::2012-08-15 11:10:23,717::task::568::TaskManager.Task::(_updateState) Task=`1633319d-222b-41d0-808c-55ac47143904`::moving from state preparing -> state acquiring
>Thread-68::DEBUG::2012-08-15 11:10:23,717::task::568::TaskManager.Task::(_updateState) Task=`1633319d-222b-41d0-808c-55ac47143904`::moving from state acquiring -> state queued
>Thread-68::DEBUG::2012-08-15 11:10:23,717::taskManager::50::TaskManager::(_queueTask) queuing task: 1633319d-222b-41d0-808c-55ac47143904
>Thread-68::DEBUG::2012-08-15 11:10:23,717::taskManager::56::TaskManager::(_queueTask) task queued: 1633319d-222b-41d0-808c-55ac47143904
>Thread-68::DEBUG::2012-08-15 11:10:23,717::task::1148::TaskManager.Task::(prepare) Task=`1633319d-222b-41d0-808c-55ac47143904`::returning
>Thread-1::DEBUG::2012-08-15 11:10:23,717::threadPool::67::Misc.ThreadPool::(setRunningTask) Number of running tasks: 1
>Thread-68::DEBUG::2012-08-15 11:10:23,718::task::957::TaskManager.Task::(_decref) Task=`1633319d-222b-41d0-808c-55ac47143904`::ref 0 aborting False
>1633319d-222b-41d0-808c-55ac47143904::DEBUG::2012-08-15 11:10:23,718::threadPool::212::Misc.ThreadPool.WorkerThread::(run) Task: 1633319d-222b-41d0-808c-55ac47143904 running: <bound method Task.commit of <storage.task.Task instance at 0x1052440>> with: None
>1633319d-222b-41d0-808c-55ac47143904::DEBUG::2012-08-15 11:10:23,718::task::1159::TaskManager.Task::(commit) Task=`1633319d-222b-41d0-808c-55ac47143904`::committing task: 1633319d-222b-41d0-808c-55ac47143904
>1633319d-222b-41d0-808c-55ac47143904::DEBUG::2012-08-15 11:10:23,719::task::568::TaskManager.Task::(_updateState) Task=`1633319d-222b-41d0-808c-55ac47143904`::moving from state queued -> state running
>1633319d-222b-41d0-808c-55ac47143904::DEBUG::2012-08-15 11:10:23,719::task::872::TaskManager.Task::(_runJobs) Task=`1633319d-222b-41d0-808c-55ac47143904`::Task.run: running job 0: spmStart: <bound method StoragePool.startSpm of <storage.sp.StoragePool object at 0x10cfc50>> (args: (1, '0', 'false', 250, 3) kwargs: {})
>1633319d-222b-41d0-808c-55ac47143904::DEBUG::2012-08-15 11:10:23,719::task::304::TaskManager.Task::(run) Task=`1633319d-222b-41d0-808c-55ac47143904`::Job.run: running spmStart: <bound method StoragePool.startSpm of <storage.sp.StoragePool object at 0x10cfc50>> (args: (1, '0', 'false', 250, 3) kwargs: {}) callback None
>1633319d-222b-41d0-808c-55ac47143904::DEBUG::2012-08-15 11:10:23,719::misc::1061::SamplingMethod::(__call__) Trying to enter sampling method (storage.sp.updateMonitoringThreads)
>1633319d-222b-41d0-808c-55ac47143904::DEBUG::2012-08-15 11:10:23,719::misc::1063::SamplingMethod::(__call__) Got in to sampling method
>1633319d-222b-41d0-808c-55ac47143904::DEBUG::2012-08-15 11:10:23,725::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=s2', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=dc2', 'POOL_DOMAINS=a074f327-d0d2-445a-af76-60a5c69fbc29:Active', 'POOL_SPM_ID=1', 'POOL_SPM_LVER=0', 'POOL_UUID=22f91e5e-fa21-4975-8fac-f6ab5191cab1', 'REMOTE_PATH=multipass.eng.lab.tlv.redhat.com:/export/images/rnd/amureini/data2', 'ROLE=Master', 'SDUUID=a074f327-d0d2-445a-af76-60a5c69fbc29', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=22ced00ae474ba3908384a3f705d9af307d93104']
>1633319d-222b-41d0-808c-55ac47143904::DEBUG::2012-08-15 11:10:23,726::misc::1071::SamplingMethod::(__call__) Returning last result
>1633319d-222b-41d0-808c-55ac47143904::DEBUG::2012-08-15 11:10:23,731::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=s2', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=dc2', 'POOL_DOMAINS=a074f327-d0d2-445a-af76-60a5c69fbc29:Active', 'POOL_SPM_ID=1', 'POOL_SPM_LVER=0', 'POOL_UUID=22f91e5e-fa21-4975-8fac-f6ab5191cab1', 'REMOTE_PATH=multipass.eng.lab.tlv.redhat.com:/export/images/rnd/amureini/data2', 'ROLE=Master', 'SDUUID=a074f327-d0d2-445a-af76-60a5c69fbc29', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=22ced00ae474ba3908384a3f705d9af307d93104']
>1633319d-222b-41d0-808c-55ac47143904::DEBUG::2012-08-15 11:10:23,737::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=s2', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=dc2', 'POOL_DOMAINS=a074f327-d0d2-445a-af76-60a5c69fbc29:Active', 'POOL_SPM_ID=1', 'POOL_SPM_LVER=0', 'POOL_UUID=22f91e5e-fa21-4975-8fac-f6ab5191cab1', 'REMOTE_PATH=multipass.eng.lab.tlv.redhat.com:/export/images/rnd/amureini/data2', 'ROLE=Master', 'SDUUID=a074f327-d0d2-445a-af76-60a5c69fbc29', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=22ced00ae474ba3908384a3f705d9af307d93104']
>1633319d-222b-41d0-808c-55ac47143904::INFO::2012-08-15 11:10:23,738::safelease::160::SANLock::(acquireHostId) Acquiring host id for domain a074f327-d0d2-445a-af76-60a5c69fbc29 (id: 1)
>1633319d-222b-41d0-808c-55ac47143904::DEBUG::2012-08-15 11:10:23,738::safelease::178::SANLock::(acquireHostId) Host id for domain a074f327-d0d2-445a-af76-60a5c69fbc29 successfully acquired (id: 1)
>1633319d-222b-41d0-808c-55ac47143904::INFO::2012-08-15 11:10:23,738::safelease::211::SANLock::(acquire) Acquiring cluster lock for domain a074f327-d0d2-445a-af76-60a5c69fbc29 (id: 1)
>1633319d-222b-41d0-808c-55ac47143904::DEBUG::2012-08-15 11:10:23,833::safelease::235::SANLock::(acquire) Cluster lock for domain a074f327-d0d2-445a-af76-60a5c69fbc29 successfully acquired (id: 1)
>1633319d-222b-41d0-808c-55ac47143904::DEBUG::2012-08-15 11:10:23,833::sp::256::Storage.StoragePool::(startSpm) spm lock acquired successfully
>1633319d-222b-41d0-808c-55ac47143904::DEBUG::2012-08-15 11:10:23,836::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=s2', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=dc2', 'POOL_DOMAINS=a074f327-d0d2-445a-af76-60a5c69fbc29:Active', 'POOL_SPM_ID=1', 'POOL_SPM_LVER=0', 'POOL_UUID=22f91e5e-fa21-4975-8fac-f6ab5191cab1', 'REMOTE_PATH=multipass.eng.lab.tlv.redhat.com:/export/images/rnd/amureini/data2', 'ROLE=Master', 'SDUUID=a074f327-d0d2-445a-af76-60a5c69fbc29', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=22ced00ae474ba3908384a3f705d9af307d93104']
>1633319d-222b-41d0-808c-55ac47143904::DEBUG::2012-08-15 11:10:23,836::persistentDict::167::Storage.PersistentDict::(transaction) Starting transaction
>1633319d-222b-41d0-808c-55ac47143904::DEBUG::2012-08-15 11:10:23,836::persistentDict::173::Storage.PersistentDict::(transaction) Flushing changes
>1633319d-222b-41d0-808c-55ac47143904::DEBUG::2012-08-15 11:10:23,836::persistentDict::299::Storage.PersistentDict::(flush) about to write lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=s2', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=dc2', 'POOL_DOMAINS=a074f327-d0d2-445a-af76-60a5c69fbc29:Active', 'POOL_SPM_ID=1', 'POOL_SPM_LVER=1', 'POOL_UUID=22f91e5e-fa21-4975-8fac-f6ab5191cab1', 'REMOTE_PATH=multipass.eng.lab.tlv.redhat.com:/export/images/rnd/amureini/data2', 'ROLE=Master', 'SDUUID=a074f327-d0d2-445a-af76-60a5c69fbc29', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=24ffdf3ba63267dba90674108c7091721a90880a']
>1633319d-222b-41d0-808c-55ac47143904::DEBUG::2012-08-15 11:10:23,887::persistentDict::175::Storage.PersistentDict::(transaction) Finished transaction
>1633319d-222b-41d0-808c-55ac47143904::DEBUG::2012-08-15 11:10:23,887::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.upgrade_22f91e5e-fa21-4975-8fac-f6ab5191cab1`ReqID=`c83fb3cd-baeb-4d48-8ff3-65b1b363f9b2`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>1633319d-222b-41d0-808c-55ac47143904::DEBUG::2012-08-15 11:10:23,887::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.upgrade_22f91e5e-fa21-4975-8fac-f6ab5191cab1' for lock type 'exclusive'
>1633319d-222b-41d0-808c-55ac47143904::DEBUG::2012-08-15 11:10:23,887::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.upgrade_22f91e5e-fa21-4975-8fac-f6ab5191cab1' is free. Now locking as 'exclusive' (1 active user)
>1633319d-222b-41d0-808c-55ac47143904::DEBUG::2012-08-15 11:10:23,887::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.upgrade_22f91e5e-fa21-4975-8fac-f6ab5191cab1`ReqID=`c83fb3cd-baeb-4d48-8ff3-65b1b363f9b2`::Granted request
>1633319d-222b-41d0-808c-55ac47143904::INFO::2012-08-15 11:10:23,888::sp::403::Storage.StoragePool::(_upgradePool) Trying to upgrade master domain `a074f327-d0d2-445a-af76-60a5c69fbc29`
>1633319d-222b-41d0-808c-55ac47143904::DEBUG::2012-08-15 11:10:23,888::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.a074f327-d0d2-445a-af76-60a5c69fbc29`ReqID=`b6f776f9-97ff-4176-acd4-6a60fe3200b6`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>1633319d-222b-41d0-808c-55ac47143904::DEBUG::2012-08-15 11:10:23,888::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.a074f327-d0d2-445a-af76-60a5c69fbc29' for lock type 'exclusive'
>1633319d-222b-41d0-808c-55ac47143904::DEBUG::2012-08-15 11:10:23,889::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.a074f327-d0d2-445a-af76-60a5c69fbc29' is free. Now locking as 'exclusive' (1 active user)
>1633319d-222b-41d0-808c-55ac47143904::DEBUG::2012-08-15 11:10:23,889::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.a074f327-d0d2-445a-af76-60a5c69fbc29`ReqID=`b6f776f9-97ff-4176-acd4-6a60fe3200b6`::Granted request
>1633319d-222b-41d0-808c-55ac47143904::DEBUG::2012-08-15 11:10:23,889::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.a074f327-d0d2-445a-af76-60a5c69fbc29'
>1633319d-222b-41d0-808c-55ac47143904::DEBUG::2012-08-15 11:10:23,889::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.a074f327-d0d2-445a-af76-60a5c69fbc29' (0 active users)
>1633319d-222b-41d0-808c-55ac47143904::DEBUG::2012-08-15 11:10:23,889::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.a074f327-d0d2-445a-af76-60a5c69fbc29' is free, finding out if anyone is waiting for it.
>1633319d-222b-41d0-808c-55ac47143904::DEBUG::2012-08-15 11:10:23,889::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.a074f327-d0d2-445a-af76-60a5c69fbc29', Clearing records.
>1633319d-222b-41d0-808c-55ac47143904::DEBUG::2012-08-15 11:10:23,890::sp::407::Storage.StoragePool::(_upgradePool) Marking all domains for upgrade
>1633319d-222b-41d0-808c-55ac47143904::DEBUG::2012-08-15 11:10:23,890::lvm::368::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>1633319d-222b-41d0-808c-55ac47143904::DEBUG::2012-08-15 11:10:23,890::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/lvm vgs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 filter = [ \\"r%.*%\\" ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1 }  backup {  retain_min = 50  retain_days = 0 } " --noheadings --units b --nosuffix --separator | -o uuid,name,attr,size,free,extent_size,extent_count,free_count,tags,vg_mda_size,vg_mda_free a074f327-d0d2-445a-af76-60a5c69fbc29' (cwd None)
>1633319d-222b-41d0-808c-55ac47143904::DEBUG::2012-08-15 11:10:23,972::__init__::1164::Storage.Misc.excCmd::(_log) FAILED: <err> = '  Volume group "a074f327-d0d2-445a-af76-60a5c69fbc29" not found\n'; <rc> = 5
>1633319d-222b-41d0-808c-55ac47143904::WARNING::2012-08-15 11:10:23,973::lvm::373::Storage.LVM::(_reloadvgs) lvm vgs failed: 5 [] ['  Volume group "a074f327-d0d2-445a-af76-60a5c69fbc29" not found']
>1633319d-222b-41d0-808c-55ac47143904::DEBUG::2012-08-15 11:10:23,974::lvm::397::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>1633319d-222b-41d0-808c-55ac47143904::DEBUG::2012-08-15 11:10:23,989::fileSD::107::Storage.StorageDomain::(__init__) Reading domain in path /rhev/data-center/mnt/multipass.eng.lab.tlv.redhat.com:_export_images_rnd_amureini_data2/a074f327-d0d2-445a-af76-60a5c69fbc29
>1633319d-222b-41d0-808c-55ac47143904::DEBUG::2012-08-15 11:10:23,989::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with FileMetadataRW backend
>1633319d-222b-41d0-808c-55ac47143904::DEBUG::2012-08-15 11:10:23,997::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=s2', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=dc2', 'POOL_DOMAINS=a074f327-d0d2-445a-af76-60a5c69fbc29:Active', 'POOL_SPM_ID=1', 'POOL_SPM_LVER=1', 'POOL_UUID=22f91e5e-fa21-4975-8fac-f6ab5191cab1', 'REMOTE_PATH=multipass.eng.lab.tlv.redhat.com:/export/images/rnd/amureini/data2', 'ROLE=Master', 'SDUUID=a074f327-d0d2-445a-af76-60a5c69fbc29', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=24ffdf3ba63267dba90674108c7091721a90880a']
>1633319d-222b-41d0-808c-55ac47143904::DEBUG::2012-08-15 11:10:23,999::fileSD::419::Storage.StorageDomain::(imageGarbageCollector) Removing remnants of deleted images []
>1633319d-222b-41d0-808c-55ac47143904::WARNING::2012-08-15 11:10:23,999::sd::348::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace a074f327-d0d2-445a-af76-60a5c69fbc29_imageNS already registered
>1633319d-222b-41d0-808c-55ac47143904::WARNING::2012-08-15 11:10:24,000::sd::356::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace a074f327-d0d2-445a-af76-60a5c69fbc29_volumeNS already registered
>1633319d-222b-41d0-808c-55ac47143904::DEBUG::2012-08-15 11:10:24,000::sp::414::Storage.StoragePool::(_upgradePool) Registering with state change event
>1633319d-222b-41d0-808c-55ac47143904::DEBUG::2012-08-15 11:10:24,000::sp::416::Storage.StoragePool::(_upgradePool) Running initial domain upgrade threads
>1633319d-222b-41d0-808c-55ac47143904::DEBUG::2012-08-15 11:10:24,000::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.upgrade_22f91e5e-fa21-4975-8fac-f6ab5191cab1'
>1633319d-222b-41d0-808c-55ac47143904::DEBUG::2012-08-15 11:10:24,000::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.upgrade_22f91e5e-fa21-4975-8fac-f6ab5191cab1' (0 active users)
>1633319d-222b-41d0-808c-55ac47143904::DEBUG::2012-08-15 11:10:24,000::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.upgrade_22f91e5e-fa21-4975-8fac-f6ab5191cab1' is free, finding out if anyone is waiting for it.
>1633319d-222b-41d0-808c-55ac47143904::DEBUG::2012-08-15 11:10:24,001::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.upgrade_22f91e5e-fa21-4975-8fac-f6ab5191cab1', Clearing records.
>1633319d-222b-41d0-808c-55ac47143904::DEBUG::2012-08-15 11:10:24,002::sp::305::Storage.StoragePool::(startSpm) ended.
>1633319d-222b-41d0-808c-55ac47143904::DEBUG::2012-08-15 11:10:24,002::task::568::TaskManager.Task::(_updateState) Task=`1633319d-222b-41d0-808c-55ac47143904`::moving from state running -> state finished
>1633319d-222b-41d0-808c-55ac47143904::DEBUG::2012-08-15 11:10:24,002::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1': < ResourceRef 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1', isValid: 'True' obj: 'None'>}
>1633319d-222b-41d0-808c-55ac47143904::DEBUG::2012-08-15 11:10:24,002::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>1633319d-222b-41d0-808c-55ac47143904::DEBUG::2012-08-15 11:10:24,002::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1'
>1633319d-222b-41d0-808c-55ac47143904::DEBUG::2012-08-15 11:10:24,003::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1' (0 active users)
>1633319d-222b-41d0-808c-55ac47143904::DEBUG::2012-08-15 11:10:24,003::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1' is free, finding out if anyone is waiting for it.
>1633319d-222b-41d0-808c-55ac47143904::DEBUG::2012-08-15 11:10:24,003::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1', Clearing records.
>1633319d-222b-41d0-808c-55ac47143904::DEBUG::2012-08-15 11:10:24,003::task::880::TaskManager.Task::(_runJobs) Task=`1633319d-222b-41d0-808c-55ac47143904`::Task.run: exit - success: result 
>1633319d-222b-41d0-808c-55ac47143904::DEBUG::2012-08-15 11:10:24,003::task::957::TaskManager.Task::(_decref) Task=`1633319d-222b-41d0-808c-55ac47143904`::ref 0 aborting False
>1633319d-222b-41d0-808c-55ac47143904::DEBUG::2012-08-15 11:10:24,003::threadPool::67::Misc.ThreadPool::(setRunningTask) Number of running tasks: 0
>Thread-93::DEBUG::2012-08-15 11:10:24,727::BindingXMLRPC::160::vds::(wrapper) [10.35.1.234]
>Thread-93::DEBUG::2012-08-15 11:10:24,728::task::568::TaskManager.Task::(_updateState) Task=`2b1f2361-3bd9-4c90-b4c7-d0ee99e96b9f`::moving from state init -> state preparing
>Thread-93::INFO::2012-08-15 11:10:24,728::logUtils::37::dispatcher::(wrapper) Run and protect: getTaskStatus(taskID='1633319d-222b-41d0-808c-55ac47143904', spUUID=None, options=None)
>Thread-93::DEBUG::2012-08-15 11:10:24,728::taskManager::93::TaskManager::(getTaskStatus) Entry. taskID: 1633319d-222b-41d0-808c-55ac47143904
>Thread-93::DEBUG::2012-08-15 11:10:24,728::taskManager::96::TaskManager::(getTaskStatus) Return. Response: {'code': 0, 'message': '1 jobs completed successfully', 'taskState': 'finished', 'taskResult': 'success', 'taskID': '1633319d-222b-41d0-808c-55ac47143904'}
>Thread-93::INFO::2012-08-15 11:10:24,728::logUtils::39::dispatcher::(wrapper) Run and protect: getTaskStatus, Return response: {'taskStatus': {'code': 0, 'message': '1 jobs completed successfully', 'taskState': 'finished', 'taskResult': 'success', 'taskID': '1633319d-222b-41d0-808c-55ac47143904'}}
>Thread-93::DEBUG::2012-08-15 11:10:24,728::task::1151::TaskManager.Task::(prepare) Task=`2b1f2361-3bd9-4c90-b4c7-d0ee99e96b9f`::finished: {'taskStatus': {'code': 0, 'message': '1 jobs completed successfully', 'taskState': 'finished', 'taskResult': 'success', 'taskID': '1633319d-222b-41d0-808c-55ac47143904'}}
>Thread-93::DEBUG::2012-08-15 11:10:24,728::task::568::TaskManager.Task::(_updateState) Task=`2b1f2361-3bd9-4c90-b4c7-d0ee99e96b9f`::moving from state preparing -> state finished
>Thread-93::DEBUG::2012-08-15 11:10:24,729::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-93::DEBUG::2012-08-15 11:10:24,729::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-93::DEBUG::2012-08-15 11:10:24,729::task::957::TaskManager.Task::(_decref) Task=`2b1f2361-3bd9-4c90-b4c7-d0ee99e96b9f`::ref 0 aborting False
>Thread-94::DEBUG::2012-08-15 11:10:24,737::BindingXMLRPC::160::vds::(wrapper) [10.35.1.234]
>Thread-94::DEBUG::2012-08-15 11:10:24,737::task::568::TaskManager.Task::(_updateState) Task=`51d7d86d-0403-4598-b8f1-39ba860882a6`::moving from state init -> state preparing
>Thread-94::INFO::2012-08-15 11:10:24,737::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='22f91e5e-fa21-4975-8fac-f6ab5191cab1', options=None)
>Thread-94::INFO::2012-08-15 11:10:24,738::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 1}}
>Thread-94::DEBUG::2012-08-15 11:10:24,738::task::1151::TaskManager.Task::(prepare) Task=`51d7d86d-0403-4598-b8f1-39ba860882a6`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 1}}
>Thread-94::DEBUG::2012-08-15 11:10:24,738::task::568::TaskManager.Task::(_updateState) Task=`51d7d86d-0403-4598-b8f1-39ba860882a6`::moving from state preparing -> state finished
>Thread-94::DEBUG::2012-08-15 11:10:24,738::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-94::DEBUG::2012-08-15 11:10:24,738::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-94::DEBUG::2012-08-15 11:10:24,738::task::957::TaskManager.Task::(_decref) Task=`51d7d86d-0403-4598-b8f1-39ba860882a6`::ref 0 aborting False
>Thread-95::DEBUG::2012-08-15 11:10:24,749::BindingXMLRPC::160::vds::(wrapper) [10.35.1.234]
>Thread-95::DEBUG::2012-08-15 11:10:24,749::task::568::TaskManager.Task::(_updateState) Task=`06868bf9-61f5-4fa6-ab3b-40d023ab6546`::moving from state init -> state preparing
>Thread-95::INFO::2012-08-15 11:10:24,749::logUtils::37::dispatcher::(wrapper) Run and protect: clearTask(taskID='1633319d-222b-41d0-808c-55ac47143904', spUUID=None, options=None)
>Thread-95::DEBUG::2012-08-15 11:10:24,749::taskManager::157::TaskManager::(clearTask) Entry. taskID: 1633319d-222b-41d0-808c-55ac47143904
>Thread-95::DEBUG::2012-08-15 11:10:24,749::taskManager::162::TaskManager::(clearTask) Return.
>Thread-95::INFO::2012-08-15 11:10:24,749::logUtils::39::dispatcher::(wrapper) Run and protect: clearTask, Return response: None
>Thread-95::DEBUG::2012-08-15 11:10:24,749::task::1151::TaskManager.Task::(prepare) Task=`06868bf9-61f5-4fa6-ab3b-40d023ab6546`::finished: None
>Thread-95::DEBUG::2012-08-15 11:10:24,750::task::568::TaskManager.Task::(_updateState) Task=`06868bf9-61f5-4fa6-ab3b-40d023ab6546`::moving from state preparing -> state finished
>Thread-95::DEBUG::2012-08-15 11:10:24,750::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-95::DEBUG::2012-08-15 11:10:24,750::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-95::DEBUG::2012-08-15 11:10:24,750::task::957::TaskManager.Task::(_decref) Task=`06868bf9-61f5-4fa6-ab3b-40d023ab6546`::ref 0 aborting False
>Thread-96::DEBUG::2012-08-15 11:10:24,838::BindingXMLRPC::160::vds::(wrapper) [10.35.1.234]
>Thread-96::DEBUG::2012-08-15 11:10:24,838::task::568::TaskManager.Task::(_updateState) Task=`aa2f84a3-db1c-412d-8cca-f6a5a778e4f8`::moving from state init -> state preparing
>Thread-96::INFO::2012-08-15 11:10:24,838::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='22f91e5e-fa21-4975-8fac-f6ab5191cab1', options=None)
>Thread-96::DEBUG::2012-08-15 11:10:24,838::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1`ReqID=`e93e683c-c89d-4638-aa47-d5b343f0d894`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-96::DEBUG::2012-08-15 11:10:24,839::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1' for lock type 'shared'
>Thread-96::DEBUG::2012-08-15 11:10:24,839::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1' is free. Now locking as 'shared' (1 active user)
>Thread-96::DEBUG::2012-08-15 11:10:24,839::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1`ReqID=`e93e683c-c89d-4638-aa47-d5b343f0d894`::Granted request
>Thread-96::DEBUG::2012-08-15 11:10:24,839::task::794::TaskManager.Task::(resourceAcquired) Task=`aa2f84a3-db1c-412d-8cca-f6a5a778e4f8`::_resourcesAcquired: Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1 (shared)
>Thread-96::DEBUG::2012-08-15 11:10:24,839::task::957::TaskManager.Task::(_decref) Task=`aa2f84a3-db1c-412d-8cca-f6a5a778e4f8`::ref 1 aborting False
>Thread-96::INFO::2012-08-15 11:10:24,842::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': 'a074f327-d0d2-445a-af76-60a5c69fbc29', 'name': 'dc2', 'version': '3', 'domains': 'a074f327-d0d2-445a-af76-60a5c69fbc29:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 1}, 'dominfo': {'a074f327-d0d2-445a-af76-60a5c69fbc29': {'status': 'Active', 'diskfree': '899762094080', 'alerts': [], 'disktotal': '977827528704'}}}
>Thread-96::DEBUG::2012-08-15 11:10:24,842::task::1151::TaskManager.Task::(prepare) Task=`aa2f84a3-db1c-412d-8cca-f6a5a778e4f8`::finished: {'info': {'spm_id': 1, 'master_uuid': 'a074f327-d0d2-445a-af76-60a5c69fbc29', 'name': 'dc2', 'version': '3', 'domains': 'a074f327-d0d2-445a-af76-60a5c69fbc29:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 1}, 'dominfo': {'a074f327-d0d2-445a-af76-60a5c69fbc29': {'status': 'Active', 'diskfree': '899762094080', 'alerts': [], 'disktotal': '977827528704'}}}
>Thread-96::DEBUG::2012-08-15 11:10:24,843::task::568::TaskManager.Task::(_updateState) Task=`aa2f84a3-db1c-412d-8cca-f6a5a778e4f8`::moving from state preparing -> state finished
>Thread-96::DEBUG::2012-08-15 11:10:24,843::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1': < ResourceRef 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1', isValid: 'True' obj: 'None'>}
>Thread-96::DEBUG::2012-08-15 11:10:24,843::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-96::DEBUG::2012-08-15 11:10:24,843::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1'
>Thread-96::DEBUG::2012-08-15 11:10:24,843::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1' (0 active users)
>Thread-96::DEBUG::2012-08-15 11:10:24,843::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1' is free, finding out if anyone is waiting for it.
>Thread-96::DEBUG::2012-08-15 11:10:24,843::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1', Clearing records.
>Thread-96::DEBUG::2012-08-15 11:10:24,843::task::957::TaskManager.Task::(_decref) Task=`aa2f84a3-db1c-412d-8cca-f6a5a778e4f8`::ref 0 aborting False
>Thread-97::DEBUG::2012-08-15 11:10:24,921::BindingXMLRPC::160::vds::(wrapper) [10.35.1.234]
>Thread-97::DEBUG::2012-08-15 11:10:24,921::task::568::TaskManager.Task::(_updateState) Task=`c69bf9ec-41cd-46ea-8319-2b16e9bd5f7e`::moving from state init -> state preparing
>Thread-97::INFO::2012-08-15 11:10:24,922::logUtils::37::dispatcher::(wrapper) Run and protect: getAllTasksInfo(spUUID=None, options=None)
>Thread-97::DEBUG::2012-08-15 11:10:24,922::taskManager::177::TaskManager::(getAllTasksInfo) Entry.
>Thread-97::DEBUG::2012-08-15 11:10:24,922::taskManager::188::TaskManager::(getAllTasksInfo) Return. Response: {}
>Thread-97::INFO::2012-08-15 11:10:24,922::logUtils::39::dispatcher::(wrapper) Run and protect: getAllTasksInfo, Return response: {'allTasksInfo': {}}
>Thread-97::DEBUG::2012-08-15 11:10:24,922::task::1151::TaskManager.Task::(prepare) Task=`c69bf9ec-41cd-46ea-8319-2b16e9bd5f7e`::finished: {'allTasksInfo': {}}
>Thread-97::DEBUG::2012-08-15 11:10:24,922::task::568::TaskManager.Task::(_updateState) Task=`c69bf9ec-41cd-46ea-8319-2b16e9bd5f7e`::moving from state preparing -> state finished
>Thread-97::DEBUG::2012-08-15 11:10:24,922::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-97::DEBUG::2012-08-15 11:10:24,922::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-97::DEBUG::2012-08-15 11:10:24,923::task::957::TaskManager.Task::(_decref) Task=`c69bf9ec-41cd-46ea-8319-2b16e9bd5f7e`::ref 0 aborting False
>Thread-98::DEBUG::2012-08-15 11:10:24,937::BindingXMLRPC::160::vds::(wrapper) [10.35.1.234]
>Thread-98::DEBUG::2012-08-15 11:10:24,937::task::568::TaskManager.Task::(_updateState) Task=`e2ea64c4-b14e-4a71-85f4-fcf095b2d8c7`::moving from state init -> state preparing
>Thread-98::INFO::2012-08-15 11:10:24,937::logUtils::37::dispatcher::(wrapper) Run and protect: getAllTasksInfo(spUUID=None, options=None)
>Thread-98::DEBUG::2012-08-15 11:10:24,937::taskManager::177::TaskManager::(getAllTasksInfo) Entry.
>Thread-98::DEBUG::2012-08-15 11:10:24,937::taskManager::188::TaskManager::(getAllTasksInfo) Return. Response: {}
>Thread-98::INFO::2012-08-15 11:10:24,937::logUtils::39::dispatcher::(wrapper) Run and protect: getAllTasksInfo, Return response: {'allTasksInfo': {}}
>Thread-98::DEBUG::2012-08-15 11:10:24,937::task::1151::TaskManager.Task::(prepare) Task=`e2ea64c4-b14e-4a71-85f4-fcf095b2d8c7`::finished: {'allTasksInfo': {}}
>Thread-98::DEBUG::2012-08-15 11:10:24,937::task::568::TaskManager.Task::(_updateState) Task=`e2ea64c4-b14e-4a71-85f4-fcf095b2d8c7`::moving from state preparing -> state finished
>Thread-98::DEBUG::2012-08-15 11:10:24,937::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-98::DEBUG::2012-08-15 11:10:24,938::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-98::DEBUG::2012-08-15 11:10:24,938::task::957::TaskManager.Task::(_decref) Task=`e2ea64c4-b14e-4a71-85f4-fcf095b2d8c7`::ref 0 aborting False
>Thread-99::DEBUG::2012-08-15 11:10:26,505::task::568::TaskManager.Task::(_updateState) Task=`ac5dea1d-d7e4-4f5d-b365-83170af0a0cc`::moving from state init -> state preparing
>Thread-99::INFO::2012-08-15 11:10:26,506::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-99::INFO::2012-08-15 11:10:26,506::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'a074f327-d0d2-445a-af76-60a5c69fbc29': {'delay': '0.00885081291199', 'lastCheck': 1345018219.06304, 'code': 0, 'valid': True}}
>Thread-99::DEBUG::2012-08-15 11:10:26,506::task::1151::TaskManager.Task::(prepare) Task=`ac5dea1d-d7e4-4f5d-b365-83170af0a0cc`::finished: {'a074f327-d0d2-445a-af76-60a5c69fbc29': {'delay': '0.00885081291199', 'lastCheck': 1345018219.06304, 'code': 0, 'valid': True}}
>Thread-99::DEBUG::2012-08-15 11:10:26,506::task::568::TaskManager.Task::(_updateState) Task=`ac5dea1d-d7e4-4f5d-b365-83170af0a0cc`::moving from state preparing -> state finished
>Thread-99::DEBUG::2012-08-15 11:10:26,506::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-99::DEBUG::2012-08-15 11:10:26,506::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-99::DEBUG::2012-08-15 11:10:26,506::task::957::TaskManager.Task::(_decref) Task=`ac5dea1d-d7e4-4f5d-b365-83170af0a0cc`::ref 0 aborting False
>Thread-105::DEBUG::2012-08-15 11:10:34,918::BindingXMLRPC::160::vds::(wrapper) [10.35.1.234]
>Thread-105::DEBUG::2012-08-15 11:10:34,918::task::568::TaskManager.Task::(_updateState) Task=`2fb2fd94-a685-401d-a780-0d90473dc813`::moving from state init -> state preparing
>Thread-105::INFO::2012-08-15 11:10:34,918::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='22f91e5e-fa21-4975-8fac-f6ab5191cab1', options=None)
>Thread-105::INFO::2012-08-15 11:10:34,918::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 1}}
>Thread-105::DEBUG::2012-08-15 11:10:34,918::task::1151::TaskManager.Task::(prepare) Task=`2fb2fd94-a685-401d-a780-0d90473dc813`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 1}}
>Thread-105::DEBUG::2012-08-15 11:10:34,918::task::568::TaskManager.Task::(_updateState) Task=`2fb2fd94-a685-401d-a780-0d90473dc813`::moving from state preparing -> state finished
>Thread-105::DEBUG::2012-08-15 11:10:34,919::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-105::DEBUG::2012-08-15 11:10:34,919::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-105::DEBUG::2012-08-15 11:10:34,919::task::957::TaskManager.Task::(_decref) Task=`2fb2fd94-a685-401d-a780-0d90473dc813`::ref 0 aborting False
>Thread-106::DEBUG::2012-08-15 11:10:34,925::BindingXMLRPC::160::vds::(wrapper) [10.35.1.234]
>Thread-106::DEBUG::2012-08-15 11:10:34,925::task::568::TaskManager.Task::(_updateState) Task=`7b44e6fc-6af2-4626-a689-68c473f745eb`::moving from state init -> state preparing
>Thread-106::INFO::2012-08-15 11:10:34,925::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='22f91e5e-fa21-4975-8fac-f6ab5191cab1', options=None)
>Thread-106::DEBUG::2012-08-15 11:10:34,926::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1`ReqID=`746c2443-bf9b-4bb6-8212-8218618393b4`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-106::DEBUG::2012-08-15 11:10:34,926::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1' for lock type 'shared'
>Thread-106::DEBUG::2012-08-15 11:10:34,926::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1' is free. Now locking as 'shared' (1 active user)
>Thread-106::DEBUG::2012-08-15 11:10:34,926::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1`ReqID=`746c2443-bf9b-4bb6-8212-8218618393b4`::Granted request
>Thread-106::DEBUG::2012-08-15 11:10:34,926::task::794::TaskManager.Task::(resourceAcquired) Task=`7b44e6fc-6af2-4626-a689-68c473f745eb`::_resourcesAcquired: Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1 (shared)
>Thread-106::DEBUG::2012-08-15 11:10:34,926::task::957::TaskManager.Task::(_decref) Task=`7b44e6fc-6af2-4626-a689-68c473f745eb`::ref 1 aborting False
>Thread-106::INFO::2012-08-15 11:10:34,929::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': 'a074f327-d0d2-445a-af76-60a5c69fbc29', 'name': 'dc2', 'version': '3', 'domains': 'a074f327-d0d2-445a-af76-60a5c69fbc29:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 1}, 'dominfo': {'a074f327-d0d2-445a-af76-60a5c69fbc29': {'status': 'Active', 'diskfree': '899762094080', 'alerts': [], 'disktotal': '977827528704'}}}
>Thread-106::DEBUG::2012-08-15 11:10:34,930::task::1151::TaskManager.Task::(prepare) Task=`7b44e6fc-6af2-4626-a689-68c473f745eb`::finished: {'info': {'spm_id': 1, 'master_uuid': 'a074f327-d0d2-445a-af76-60a5c69fbc29', 'name': 'dc2', 'version': '3', 'domains': 'a074f327-d0d2-445a-af76-60a5c69fbc29:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 1}, 'dominfo': {'a074f327-d0d2-445a-af76-60a5c69fbc29': {'status': 'Active', 'diskfree': '899762094080', 'alerts': [], 'disktotal': '977827528704'}}}
>Thread-106::DEBUG::2012-08-15 11:10:34,930::task::568::TaskManager.Task::(_updateState) Task=`7b44e6fc-6af2-4626-a689-68c473f745eb`::moving from state preparing -> state finished
>Thread-106::DEBUG::2012-08-15 11:10:34,930::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1': < ResourceRef 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1', isValid: 'True' obj: 'None'>}
>Thread-106::DEBUG::2012-08-15 11:10:34,930::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-106::DEBUG::2012-08-15 11:10:34,930::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1'
>Thread-106::DEBUG::2012-08-15 11:10:34,930::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1' (0 active users)
>Thread-106::DEBUG::2012-08-15 11:10:34,930::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1' is free, finding out if anyone is waiting for it.
>Thread-106::DEBUG::2012-08-15 11:10:34,931::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1', Clearing records.
>Thread-106::DEBUG::2012-08-15 11:10:34,931::task::957::TaskManager.Task::(_decref) Task=`7b44e6fc-6af2-4626-a689-68c473f745eb`::ref 0 aborting False
>Thread-107::DEBUG::2012-08-15 11:10:36,650::task::568::TaskManager.Task::(_updateState) Task=`ae30bc1d-3030-43ff-8626-a0294db3eadf`::moving from state init -> state preparing
>Thread-107::INFO::2012-08-15 11:10:36,650::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-107::INFO::2012-08-15 11:10:36,651::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'a074f327-d0d2-445a-af76-60a5c69fbc29': {'delay': '0.00676107406616', 'lastCheck': 1345018229.0761189, 'code': 0, 'valid': True}}
>Thread-107::DEBUG::2012-08-15 11:10:36,651::task::1151::TaskManager.Task::(prepare) Task=`ae30bc1d-3030-43ff-8626-a0294db3eadf`::finished: {'a074f327-d0d2-445a-af76-60a5c69fbc29': {'delay': '0.00676107406616', 'lastCheck': 1345018229.0761189, 'code': 0, 'valid': True}}
>Thread-107::DEBUG::2012-08-15 11:10:36,651::task::568::TaskManager.Task::(_updateState) Task=`ae30bc1d-3030-43ff-8626-a0294db3eadf`::moving from state preparing -> state finished
>Thread-107::DEBUG::2012-08-15 11:10:36,651::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-107::DEBUG::2012-08-15 11:10:36,651::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-107::DEBUG::2012-08-15 11:10:36,651::task::957::TaskManager.Task::(_decref) Task=`ae30bc1d-3030-43ff-8626-a0294db3eadf`::ref 0 aborting False
>Thread-110::DEBUG::2012-08-15 11:10:39,527::BindingXMLRPC::160::vds::(wrapper) [10.35.1.234]
>Thread-110::DEBUG::2012-08-15 11:10:39,528::task::568::TaskManager.Task::(_updateState) Task=`c18b287f-0690-4ea6-8abe-0df98c6be7fa`::moving from state init -> state preparing
>Thread-110::INFO::2012-08-15 11:10:39,528::logUtils::37::dispatcher::(wrapper) Run and protect: updateVM(spUUID='22f91e5e-fa21-4975-8fac-f6ab5191cab1', vmList=[{'imglist': '', 'ovf': '<?xml version=\'1.0\' encoding=\'UTF-8\'?><ovf:Envelope xmlns:ovf="http://schemas.dmtf.org/ovf/envelope/1/" xmlns:rasd="http://schemas.dmtf.org/wbem/wscim/1/cim-schema/2/CIM_ResourceAllocationSettingData" xmlns:vssd="http://schemas.dmtf.org/wbem/wscim/1/cim-schema/2/CIM_VirtualSystemSettingData" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" ovf:version="3.1.0.0"><References/><Section xsi:type="ovf:NetworkSection_Type"><Info>List of networks</Info><Network ovf:name="Network 1"/></Section><Section xsi:type="ovf:DiskSection_Type"><Info>List of Virtual Disks</Info></Section><Content ovf:id="out" xsi:type="ovf:VirtualSystem_Type"><Name>vm</Name><TemplateId>00000000-0000-0000-0000-000000000000</TemplateId><TemplateName>Blank</TemplateName><Description></Description><Domain></Domain><CreationDate>2012/08/15 08:10:25</CreationDate><ExportDate>2012/08/15 08:10:39</ExportDate><IsInitilized>false</IsInitilized><IsAutoSuspend>false</IsAutoSuspend><TimeZone></TimeZone><IsStateless>false</IsStateless><Origin>3</Origin><default_boot_sequence>0</default_boot_sequence><VmType>1</VmType><DefaultDisplayType>1</DefaultDisplayType><MinAllocatedMem>512</MinAllocatedMem><Section ovf:id="5ac32111-d4bc-4d6a-b18a-c2455d79ea81" ovf:required="false" xsi:type="ovf:OperatingSystemSection_Type"><Info>Guest Operating System</Info><Description>Unassigned</Description></Section><Section xsi:type="ovf:VirtualHardwareSection_Type"><Info>1 CPU, 512 Memeory</Info><System><vssd:VirtualSystemType>ENGINE 3.1.0.0</vssd:VirtualSystemType></System><Item><rasd:Caption>1 virtual cpu</rasd:Caption><rasd:Description>Number of virtual CPU</rasd:Description><rasd:InstanceId>1</rasd:InstanceId><rasd:ResourceType>3</rasd:ResourceType><rasd:num_of_sockets>1</rasd:num_of_sockets><rasd:cpu_per_socket>1</rasd:cpu_per_socket></Item><Item><rasd:Caption>512 MB of memory</rasd:Caption><rasd:Description>Memory Size</rasd:Description><rasd:InstanceId>2</rasd:InstanceId><rasd:ResourceType>4</rasd:ResourceType><rasd:AllocationUnits>MegaBytes</rasd:AllocationUnits><rasd:VirtualQuantity>512</rasd:VirtualQuantity></Item><Item><rasd:Caption>USB Controller</rasd:Caption><rasd:InstanceId>3</rasd:InstanceId><rasd:ResourceType>23</rasd:ResourceType><rasd:UsbPolicy>DISABLED</rasd:UsbPolicy></Item><Item><rasd:Caption>Graphical Controller</rasd:Caption><rasd:InstanceId>44484378-4e4e-4957-a040-2d766d322241</rasd:InstanceId><rasd:ResourceType>20</rasd:ResourceType><rasd:VirtualQuantity>1</rasd:VirtualQuantity><Type>video</Type><Device>qxl</Device><rasd:Address></rasd:Address><BootOrder>0</BootOrder><IsPlugged>true</IsPlugged><IsReadOnly>false</IsReadOnly><Alias></Alias><SpecParams><vram>65536</vram></SpecParams></Item><Item><rasd:ResourceType>0</rasd:ResourceType><rasd:InstanceId>999cbb14-ff34-4013-a2e7-3e18e75e585d</rasd:InstanceId><Type>balloon</Type><Device>memballoon</Device><rasd:Address></rasd:Address><BootOrder>0</BootOrder><IsPlugged>true</IsPlugged><IsReadOnly>true</IsReadOnly><Alias></Alias><SpecParams><model>virtio</model></SpecParams></Item><Item><rasd:ResourceType>0</rasd:ResourceType><rasd:InstanceId>999cbb14-ff34-4013-a2e7-3e18e75e585d</rasd:InstanceId><Type>balloon</Type><Device>memballoon</Device><rasd:Address></rasd:Address><BootOrder>0</BootOrder><IsPlugged>true</IsPlugged><IsReadOnly>true</IsReadOnly><Alias></Alias><SpecParams><model>virtio</model></SpecParams></Item></Section></Content></ovf:Envelope>\n', 'vm': '5ac32111-d4bc-4d6a-b18a-c2455d79ea81'}], sdUUID=None, options=None)
>Thread-110::DEBUG::2012-08-15 11:10:39,528::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1`ReqID=`b47d6d7f-b09f-4026-aa99-7f4c5644e8e0`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-110::DEBUG::2012-08-15 11:10:39,528::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1' for lock type 'shared'
>Thread-110::DEBUG::2012-08-15 11:10:39,528::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1' is free. Now locking as 'shared' (1 active user)
>Thread-110::DEBUG::2012-08-15 11:10:39,529::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1`ReqID=`b47d6d7f-b09f-4026-aa99-7f4c5644e8e0`::Granted request
>Thread-110::DEBUG::2012-08-15 11:10:39,529::task::794::TaskManager.Task::(resourceAcquired) Task=`c18b287f-0690-4ea6-8abe-0df98c6be7fa`::_resourcesAcquired: Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1 (shared)
>Thread-110::DEBUG::2012-08-15 11:10:39,529::task::957::TaskManager.Task::(_decref) Task=`c18b287f-0690-4ea6-8abe-0df98c6be7fa`::ref 1 aborting False
>Thread-110::INFO::2012-08-15 11:10:39,529::sp::1247::Storage.StoragePool::(updateVM) spUUID=22f91e5e-fa21-4975-8fac-f6ab5191cab1 sdUUID=a074f327-d0d2-445a-af76-60a5c69fbc29
>Thread-110::INFO::2012-08-15 11:10:39,529::sp::1258::Storage.StoragePool::(updateVM) vmUUID=5ac32111-d4bc-4d6a-b18a-c2455d79ea81 imgList=['']
>Thread-110::INFO::2012-08-15 11:10:39,633::logUtils::39::dispatcher::(wrapper) Run and protect: updateVM, Return response: None
>Thread-110::DEBUG::2012-08-15 11:10:39,633::task::1151::TaskManager.Task::(prepare) Task=`c18b287f-0690-4ea6-8abe-0df98c6be7fa`::finished: None
>Thread-110::DEBUG::2012-08-15 11:10:39,633::task::568::TaskManager.Task::(_updateState) Task=`c18b287f-0690-4ea6-8abe-0df98c6be7fa`::moving from state preparing -> state finished
>Thread-110::DEBUG::2012-08-15 11:10:39,633::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1': < ResourceRef 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1', isValid: 'True' obj: 'None'>}
>Thread-110::DEBUG::2012-08-15 11:10:39,633::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-110::DEBUG::2012-08-15 11:10:39,633::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1'
>Thread-110::DEBUG::2012-08-15 11:10:39,634::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1' (0 active users)
>Thread-110::DEBUG::2012-08-15 11:10:39,634::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1' is free, finding out if anyone is waiting for it.
>Thread-110::DEBUG::2012-08-15 11:10:39,634::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1', Clearing records.
>Thread-110::DEBUG::2012-08-15 11:10:39,634::task::957::TaskManager.Task::(_decref) Task=`c18b287f-0690-4ea6-8abe-0df98c6be7fa`::ref 0 aborting False
>Thread-114::DEBUG::2012-08-15 11:10:44,975::BindingXMLRPC::160::vds::(wrapper) [10.35.1.234]
>Thread-114::DEBUG::2012-08-15 11:10:44,975::task::568::TaskManager.Task::(_updateState) Task=`4156a011-beb1-4d06-bea6-777fc9d24656`::moving from state init -> state preparing
>Thread-114::INFO::2012-08-15 11:10:44,976::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='22f91e5e-fa21-4975-8fac-f6ab5191cab1', options=None)
>Thread-114::INFO::2012-08-15 11:10:44,976::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 1}}
>Thread-114::DEBUG::2012-08-15 11:10:44,976::task::1151::TaskManager.Task::(prepare) Task=`4156a011-beb1-4d06-bea6-777fc9d24656`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 1}}
>Thread-114::DEBUG::2012-08-15 11:10:44,976::task::568::TaskManager.Task::(_updateState) Task=`4156a011-beb1-4d06-bea6-777fc9d24656`::moving from state preparing -> state finished
>Thread-114::DEBUG::2012-08-15 11:10:44,976::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-114::DEBUG::2012-08-15 11:10:44,976::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-114::DEBUG::2012-08-15 11:10:44,976::task::957::TaskManager.Task::(_decref) Task=`4156a011-beb1-4d06-bea6-777fc9d24656`::ref 0 aborting False
>Thread-115::DEBUG::2012-08-15 11:10:44,981::BindingXMLRPC::160::vds::(wrapper) [10.35.1.234]
>Thread-115::DEBUG::2012-08-15 11:10:44,981::task::568::TaskManager.Task::(_updateState) Task=`a9edc9c1-06fb-4bb8-beaf-54a00b672fb8`::moving from state init -> state preparing
>Thread-115::INFO::2012-08-15 11:10:44,982::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='22f91e5e-fa21-4975-8fac-f6ab5191cab1', options=None)
>Thread-115::DEBUG::2012-08-15 11:10:44,982::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1`ReqID=`f5717dbe-11d1-4e37-9a1d-22a83539a5c0`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-115::DEBUG::2012-08-15 11:10:44,982::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1' for lock type 'shared'
>Thread-115::DEBUG::2012-08-15 11:10:44,982::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1' is free. Now locking as 'shared' (1 active user)
>Thread-115::DEBUG::2012-08-15 11:10:44,982::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1`ReqID=`f5717dbe-11d1-4e37-9a1d-22a83539a5c0`::Granted request
>Thread-115::DEBUG::2012-08-15 11:10:44,983::task::794::TaskManager.Task::(resourceAcquired) Task=`a9edc9c1-06fb-4bb8-beaf-54a00b672fb8`::_resourcesAcquired: Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1 (shared)
>Thread-115::DEBUG::2012-08-15 11:10:44,983::task::957::TaskManager.Task::(_decref) Task=`a9edc9c1-06fb-4bb8-beaf-54a00b672fb8`::ref 1 aborting False
>Thread-115::INFO::2012-08-15 11:10:44,985::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': 'a074f327-d0d2-445a-af76-60a5c69fbc29', 'name': 'dc2', 'version': '3', 'domains': 'a074f327-d0d2-445a-af76-60a5c69fbc29:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 1}, 'dominfo': {'a074f327-d0d2-445a-af76-60a5c69fbc29': {'status': 'Active', 'diskfree': '899762094080', 'alerts': [], 'disktotal': '977827528704'}}}
>Thread-115::DEBUG::2012-08-15 11:10:44,985::task::1151::TaskManager.Task::(prepare) Task=`a9edc9c1-06fb-4bb8-beaf-54a00b672fb8`::finished: {'info': {'spm_id': 1, 'master_uuid': 'a074f327-d0d2-445a-af76-60a5c69fbc29', 'name': 'dc2', 'version': '3', 'domains': 'a074f327-d0d2-445a-af76-60a5c69fbc29:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 1}, 'dominfo': {'a074f327-d0d2-445a-af76-60a5c69fbc29': {'status': 'Active', 'diskfree': '899762094080', 'alerts': [], 'disktotal': '977827528704'}}}
>Thread-115::DEBUG::2012-08-15 11:10:44,985::task::568::TaskManager.Task::(_updateState) Task=`a9edc9c1-06fb-4bb8-beaf-54a00b672fb8`::moving from state preparing -> state finished
>Thread-115::DEBUG::2012-08-15 11:10:44,985::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1': < ResourceRef 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1', isValid: 'True' obj: 'None'>}
>Thread-115::DEBUG::2012-08-15 11:10:44,985::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-115::DEBUG::2012-08-15 11:10:44,985::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1'
>Thread-115::DEBUG::2012-08-15 11:10:44,985::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1' (0 active users)
>Thread-115::DEBUG::2012-08-15 11:10:44,985::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1' is free, finding out if anyone is waiting for it.
>Thread-115::DEBUG::2012-08-15 11:10:44,986::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1', Clearing records.
>Thread-115::DEBUG::2012-08-15 11:10:44,986::task::957::TaskManager.Task::(_decref) Task=`a9edc9c1-06fb-4bb8-beaf-54a00b672fb8`::ref 0 aborting False
>Thread-116::DEBUG::2012-08-15 11:10:46,783::task::568::TaskManager.Task::(_updateState) Task=`7630f09e-78d8-4aeb-b825-c0efe59dc8ef`::moving from state init -> state preparing
>Thread-116::INFO::2012-08-15 11:10:46,783::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-116::INFO::2012-08-15 11:10:46,783::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'a074f327-d0d2-445a-af76-60a5c69fbc29': {'delay': '0.00629997253418', 'lastCheck': 1345018239.088181, 'code': 0, 'valid': True}}
>Thread-116::DEBUG::2012-08-15 11:10:46,783::task::1151::TaskManager.Task::(prepare) Task=`7630f09e-78d8-4aeb-b825-c0efe59dc8ef`::finished: {'a074f327-d0d2-445a-af76-60a5c69fbc29': {'delay': '0.00629997253418', 'lastCheck': 1345018239.088181, 'code': 0, 'valid': True}}
>Thread-116::DEBUG::2012-08-15 11:10:46,783::task::568::TaskManager.Task::(_updateState) Task=`7630f09e-78d8-4aeb-b825-c0efe59dc8ef`::moving from state preparing -> state finished
>Thread-116::DEBUG::2012-08-15 11:10:46,784::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-116::DEBUG::2012-08-15 11:10:46,784::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-116::DEBUG::2012-08-15 11:10:46,784::task::957::TaskManager.Task::(_decref) Task=`7630f09e-78d8-4aeb-b825-c0efe59dc8ef`::ref 0 aborting False
>Thread-118::DEBUG::2012-08-15 11:10:47,880::BindingXMLRPC::160::vds::(wrapper) [10.35.1.234]
>Thread-118::DEBUG::2012-08-15 11:10:47,880::task::568::TaskManager.Task::(_updateState) Task=`39620050-2700-4ffa-bf55-917e0a7c0638`::moving from state init -> state preparing
>Thread-118::INFO::2012-08-15 11:10:47,881::logUtils::37::dispatcher::(wrapper) Run and protect: updateVM(spUUID='22f91e5e-fa21-4975-8fac-f6ab5191cab1', vmList=[{'imglist': '', 'ovf': '<?xml version=\'1.0\' encoding=\'UTF-8\'?><ovf:Envelope xmlns:ovf="http://schemas.dmtf.org/ovf/envelope/1/" xmlns:rasd="http://schemas.dmtf.org/wbem/wscim/1/cim-schema/2/CIM_ResourceAllocationSettingData" xmlns:vssd="http://schemas.dmtf.org/wbem/wscim/1/cim-schema/2/CIM_VirtualSystemSettingData" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" ovf:version="3.1.0.0"><References/><Section xsi:type="ovf:NetworkSection_Type"><Info>List of networks</Info><Network ovf:name="Network 1"/></Section><Section xsi:type="ovf:DiskSection_Type"><Info>List of Virtual Disks</Info></Section><Content ovf:id="out" xsi:type="ovf:VirtualSystem_Type"><Name>vm</Name><TemplateId>00000000-0000-0000-0000-000000000000</TemplateId><TemplateName>Blank</TemplateName><Description></Description><Domain></Domain><CreationDate>2012/08/15 08:10:25</CreationDate><ExportDate>2012/08/15 08:10:47</ExportDate><IsInitilized>false</IsInitilized><IsAutoSuspend>false</IsAutoSuspend><TimeZone></TimeZone><IsStateless>false</IsStateless><Origin>3</Origin><default_boot_sequence>0</default_boot_sequence><VmType>1</VmType><DefaultDisplayType>1</DefaultDisplayType><MinAllocatedMem>512</MinAllocatedMem><Section ovf:id="5ac32111-d4bc-4d6a-b18a-c2455d79ea81" ovf:required="false" xsi:type="ovf:OperatingSystemSection_Type"><Info>Guest Operating System</Info><Description>Unassigned</Description></Section><Section xsi:type="ovf:VirtualHardwareSection_Type"><Info>1 CPU, 512 Memeory</Info><System><vssd:VirtualSystemType>ENGINE 3.1.0.0</vssd:VirtualSystemType></System><Item><rasd:Caption>1 virtual cpu</rasd:Caption><rasd:Description>Number of virtual CPU</rasd:Description><rasd:InstanceId>1</rasd:InstanceId><rasd:ResourceType>3</rasd:ResourceType><rasd:num_of_sockets>1</rasd:num_of_sockets><rasd:cpu_per_socket>1</rasd:cpu_per_socket></Item><Item><rasd:Caption>512 MB of memory</rasd:Caption><rasd:Description>Memory Size</rasd:Description><rasd:InstanceId>2</rasd:InstanceId><rasd:ResourceType>4</rasd:ResourceType><rasd:AllocationUnits>MegaBytes</rasd:AllocationUnits><rasd:VirtualQuantity>512</rasd:VirtualQuantity></Item><Item><rasd:Caption>USB Controller</rasd:Caption><rasd:InstanceId>3</rasd:InstanceId><rasd:ResourceType>23</rasd:ResourceType><rasd:UsbPolicy>DISABLED</rasd:UsbPolicy></Item><Item><rasd:Caption>Graphical Controller</rasd:Caption><rasd:InstanceId>9d197f8f-5134-4844-a587-097237268855</rasd:InstanceId><rasd:ResourceType>20</rasd:ResourceType><rasd:VirtualQuantity>1</rasd:VirtualQuantity><Type>video</Type><Device>qxl</Device><rasd:Address></rasd:Address><BootOrder>0</BootOrder><IsPlugged>true</IsPlugged><IsReadOnly>false</IsReadOnly><Alias></Alias><SpecParams><vram>65536</vram></SpecParams></Item><Item><rasd:ResourceType>0</rasd:ResourceType><rasd:InstanceId>31eb492c-3d07-44f7-9930-dc523b5c30d3</rasd:InstanceId><Type>balloon</Type><Device>memballoon</Device><rasd:Address></rasd:Address><BootOrder>0</BootOrder><IsPlugged>true</IsPlugged><IsReadOnly>true</IsReadOnly><Alias></Alias><SpecParams><model>virtio</model></SpecParams></Item></Section></Content></ovf:Envelope>\n', 'vm': '5ac32111-d4bc-4d6a-b18a-c2455d79ea81'}], sdUUID=None, options=None)
>Thread-118::DEBUG::2012-08-15 11:10:47,881::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1`ReqID=`0eb9ff3c-b66f-4fbb-81f8-917c4e63a695`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-118::DEBUG::2012-08-15 11:10:47,881::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1' for lock type 'shared'
>Thread-118::DEBUG::2012-08-15 11:10:47,881::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1' is free. Now locking as 'shared' (1 active user)
>Thread-118::DEBUG::2012-08-15 11:10:47,881::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1`ReqID=`0eb9ff3c-b66f-4fbb-81f8-917c4e63a695`::Granted request
>Thread-118::DEBUG::2012-08-15 11:10:47,882::task::794::TaskManager.Task::(resourceAcquired) Task=`39620050-2700-4ffa-bf55-917e0a7c0638`::_resourcesAcquired: Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1 (shared)
>Thread-118::DEBUG::2012-08-15 11:10:47,882::task::957::TaskManager.Task::(_decref) Task=`39620050-2700-4ffa-bf55-917e0a7c0638`::ref 1 aborting False
>Thread-118::INFO::2012-08-15 11:10:47,882::sp::1247::Storage.StoragePool::(updateVM) spUUID=22f91e5e-fa21-4975-8fac-f6ab5191cab1 sdUUID=a074f327-d0d2-445a-af76-60a5c69fbc29
>Thread-118::INFO::2012-08-15 11:10:47,882::sp::1258::Storage.StoragePool::(updateVM) vmUUID=5ac32111-d4bc-4d6a-b18a-c2455d79ea81 imgList=['']
>Thread-118::INFO::2012-08-15 11:10:47,959::logUtils::39::dispatcher::(wrapper) Run and protect: updateVM, Return response: None
>Thread-118::DEBUG::2012-08-15 11:10:47,959::task::1151::TaskManager.Task::(prepare) Task=`39620050-2700-4ffa-bf55-917e0a7c0638`::finished: None
>Thread-118::DEBUG::2012-08-15 11:10:47,959::task::568::TaskManager.Task::(_updateState) Task=`39620050-2700-4ffa-bf55-917e0a7c0638`::moving from state preparing -> state finished
>Thread-118::DEBUG::2012-08-15 11:10:47,959::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1': < ResourceRef 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1', isValid: 'True' obj: 'None'>}
>Thread-118::DEBUG::2012-08-15 11:10:47,959::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-118::DEBUG::2012-08-15 11:10:47,959::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1'
>Thread-118::DEBUG::2012-08-15 11:10:47,959::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1' (0 active users)
>Thread-118::DEBUG::2012-08-15 11:10:47,960::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1' is free, finding out if anyone is waiting for it.
>Thread-118::DEBUG::2012-08-15 11:10:47,960::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1', Clearing records.
>Thread-118::DEBUG::2012-08-15 11:10:47,960::task::957::TaskManager.Task::(_decref) Task=`39620050-2700-4ffa-bf55-917e0a7c0638`::ref 0 aborting False
>Thread-123::DEBUG::2012-08-15 11:10:55,063::BindingXMLRPC::160::vds::(wrapper) [10.35.1.234]
>Thread-123::DEBUG::2012-08-15 11:10:55,063::task::568::TaskManager.Task::(_updateState) Task=`5b523f68-c51e-4cc1-83a7-46f87f68be9b`::moving from state init -> state preparing
>Thread-123::INFO::2012-08-15 11:10:55,063::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='22f91e5e-fa21-4975-8fac-f6ab5191cab1', options=None)
>Thread-123::INFO::2012-08-15 11:10:55,064::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 1}}
>Thread-123::DEBUG::2012-08-15 11:10:55,064::task::1151::TaskManager.Task::(prepare) Task=`5b523f68-c51e-4cc1-83a7-46f87f68be9b`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 1}}
>Thread-123::DEBUG::2012-08-15 11:10:55,064::task::568::TaskManager.Task::(_updateState) Task=`5b523f68-c51e-4cc1-83a7-46f87f68be9b`::moving from state preparing -> state finished
>Thread-123::DEBUG::2012-08-15 11:10:55,064::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-123::DEBUG::2012-08-15 11:10:55,064::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-123::DEBUG::2012-08-15 11:10:55,064::task::957::TaskManager.Task::(_decref) Task=`5b523f68-c51e-4cc1-83a7-46f87f68be9b`::ref 0 aborting False
>Thread-124::DEBUG::2012-08-15 11:10:55,069::BindingXMLRPC::160::vds::(wrapper) [10.35.1.234]
>Thread-124::DEBUG::2012-08-15 11:10:55,070::task::568::TaskManager.Task::(_updateState) Task=`e03867ca-d730-47fb-93bc-1046bd277456`::moving from state init -> state preparing
>Thread-124::INFO::2012-08-15 11:10:55,070::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='22f91e5e-fa21-4975-8fac-f6ab5191cab1', options=None)
>Thread-124::DEBUG::2012-08-15 11:10:55,070::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1`ReqID=`6be5245a-3339-4d3e-9dc2-a407f9bc954d`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-124::DEBUG::2012-08-15 11:10:55,070::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1' for lock type 'shared'
>Thread-124::DEBUG::2012-08-15 11:10:55,071::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1' is free. Now locking as 'shared' (1 active user)
>Thread-124::DEBUG::2012-08-15 11:10:55,071::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1`ReqID=`6be5245a-3339-4d3e-9dc2-a407f9bc954d`::Granted request
>Thread-124::DEBUG::2012-08-15 11:10:55,071::task::794::TaskManager.Task::(resourceAcquired) Task=`e03867ca-d730-47fb-93bc-1046bd277456`::_resourcesAcquired: Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1 (shared)
>Thread-124::DEBUG::2012-08-15 11:10:55,071::task::957::TaskManager.Task::(_decref) Task=`e03867ca-d730-47fb-93bc-1046bd277456`::ref 1 aborting False
>Thread-124::INFO::2012-08-15 11:10:55,074::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': 'a074f327-d0d2-445a-af76-60a5c69fbc29', 'name': 'dc2', 'version': '3', 'domains': 'a074f327-d0d2-445a-af76-60a5c69fbc29:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 1}, 'dominfo': {'a074f327-d0d2-445a-af76-60a5c69fbc29': {'status': 'Active', 'diskfree': '899762094080', 'alerts': [], 'disktotal': '977827528704'}}}
>Thread-124::DEBUG::2012-08-15 11:10:55,074::task::1151::TaskManager.Task::(prepare) Task=`e03867ca-d730-47fb-93bc-1046bd277456`::finished: {'info': {'spm_id': 1, 'master_uuid': 'a074f327-d0d2-445a-af76-60a5c69fbc29', 'name': 'dc2', 'version': '3', 'domains': 'a074f327-d0d2-445a-af76-60a5c69fbc29:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 1}, 'dominfo': {'a074f327-d0d2-445a-af76-60a5c69fbc29': {'status': 'Active', 'diskfree': '899762094080', 'alerts': [], 'disktotal': '977827528704'}}}
>Thread-124::DEBUG::2012-08-15 11:10:55,074::task::568::TaskManager.Task::(_updateState) Task=`e03867ca-d730-47fb-93bc-1046bd277456`::moving from state preparing -> state finished
>Thread-124::DEBUG::2012-08-15 11:10:55,074::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1': < ResourceRef 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1', isValid: 'True' obj: 'None'>}
>Thread-124::DEBUG::2012-08-15 11:10:55,075::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-124::DEBUG::2012-08-15 11:10:55,075::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1'
>Thread-124::DEBUG::2012-08-15 11:10:55,075::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1' (0 active users)
>Thread-124::DEBUG::2012-08-15 11:10:55,075::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1' is free, finding out if anyone is waiting for it.
>Thread-124::DEBUG::2012-08-15 11:10:55,075::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1', Clearing records.
>Thread-124::DEBUG::2012-08-15 11:10:55,075::task::957::TaskManager.Task::(_decref) Task=`e03867ca-d730-47fb-93bc-1046bd277456`::ref 0 aborting False
>Thread-125::DEBUG::2012-08-15 11:10:56,897::task::568::TaskManager.Task::(_updateState) Task=`c03e8c9a-3a98-4e99-ad1c-58f0bfe7e95a`::moving from state init -> state preparing
>Thread-125::INFO::2012-08-15 11:10:56,897::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-125::INFO::2012-08-15 11:10:56,898::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'a074f327-d0d2-445a-af76-60a5c69fbc29': {'delay': '0.00773906707764', 'lastCheck': 1345018249.105021, 'code': 0, 'valid': True}}
>Thread-125::DEBUG::2012-08-15 11:10:56,898::task::1151::TaskManager.Task::(prepare) Task=`c03e8c9a-3a98-4e99-ad1c-58f0bfe7e95a`::finished: {'a074f327-d0d2-445a-af76-60a5c69fbc29': {'delay': '0.00773906707764', 'lastCheck': 1345018249.105021, 'code': 0, 'valid': True}}
>Thread-125::DEBUG::2012-08-15 11:10:56,898::task::568::TaskManager.Task::(_updateState) Task=`c03e8c9a-3a98-4e99-ad1c-58f0bfe7e95a`::moving from state preparing -> state finished
>Thread-125::DEBUG::2012-08-15 11:10:56,898::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-125::DEBUG::2012-08-15 11:10:56,898::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-125::DEBUG::2012-08-15 11:10:56,898::task::957::TaskManager.Task::(_decref) Task=`c03e8c9a-3a98-4e99-ad1c-58f0bfe7e95a`::ref 0 aborting False
>Thread-131::DEBUG::2012-08-15 11:11:05,158::BindingXMLRPC::160::vds::(wrapper) [10.35.1.234]
>Thread-131::DEBUG::2012-08-15 11:11:05,158::task::568::TaskManager.Task::(_updateState) Task=`87803cfc-cff0-45a7-b179-80a07a72a431`::moving from state init -> state preparing
>Thread-131::INFO::2012-08-15 11:11:05,159::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='22f91e5e-fa21-4975-8fac-f6ab5191cab1', options=None)
>Thread-131::INFO::2012-08-15 11:11:05,159::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 1}}
>Thread-131::DEBUG::2012-08-15 11:11:05,159::task::1151::TaskManager.Task::(prepare) Task=`87803cfc-cff0-45a7-b179-80a07a72a431`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 1}}
>Thread-131::DEBUG::2012-08-15 11:11:05,159::task::568::TaskManager.Task::(_updateState) Task=`87803cfc-cff0-45a7-b179-80a07a72a431`::moving from state preparing -> state finished
>Thread-131::DEBUG::2012-08-15 11:11:05,159::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-131::DEBUG::2012-08-15 11:11:05,159::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-131::DEBUG::2012-08-15 11:11:05,159::task::957::TaskManager.Task::(_decref) Task=`87803cfc-cff0-45a7-b179-80a07a72a431`::ref 0 aborting False
>Thread-132::DEBUG::2012-08-15 11:11:05,163::BindingXMLRPC::160::vds::(wrapper) [10.35.1.234]
>Thread-132::DEBUG::2012-08-15 11:11:05,163::task::568::TaskManager.Task::(_updateState) Task=`af8d7709-102d-444a-b0e9-ae0c3f148cda`::moving from state init -> state preparing
>Thread-132::INFO::2012-08-15 11:11:05,163::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='22f91e5e-fa21-4975-8fac-f6ab5191cab1', options=None)
>Thread-132::DEBUG::2012-08-15 11:11:05,164::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1`ReqID=`9222f12f-c824-4459-9cf3-57a62e231d6c`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-132::DEBUG::2012-08-15 11:11:05,164::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1' for lock type 'shared'
>Thread-132::DEBUG::2012-08-15 11:11:05,164::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1' is free. Now locking as 'shared' (1 active user)
>Thread-132::DEBUG::2012-08-15 11:11:05,164::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1`ReqID=`9222f12f-c824-4459-9cf3-57a62e231d6c`::Granted request
>Thread-132::DEBUG::2012-08-15 11:11:05,165::task::794::TaskManager.Task::(resourceAcquired) Task=`af8d7709-102d-444a-b0e9-ae0c3f148cda`::_resourcesAcquired: Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1 (shared)
>Thread-132::DEBUG::2012-08-15 11:11:05,165::task::957::TaskManager.Task::(_decref) Task=`af8d7709-102d-444a-b0e9-ae0c3f148cda`::ref 1 aborting False
>Thread-132::INFO::2012-08-15 11:11:05,168::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': 'a074f327-d0d2-445a-af76-60a5c69fbc29', 'name': 'dc2', 'version': '3', 'domains': 'a074f327-d0d2-445a-af76-60a5c69fbc29:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 1}, 'dominfo': {'a074f327-d0d2-445a-af76-60a5c69fbc29': {'status': 'Active', 'diskfree': '899762094080', 'alerts': [], 'disktotal': '977827528704'}}}
>Thread-132::DEBUG::2012-08-15 11:11:05,168::task::1151::TaskManager.Task::(prepare) Task=`af8d7709-102d-444a-b0e9-ae0c3f148cda`::finished: {'info': {'spm_id': 1, 'master_uuid': 'a074f327-d0d2-445a-af76-60a5c69fbc29', 'name': 'dc2', 'version': '3', 'domains': 'a074f327-d0d2-445a-af76-60a5c69fbc29:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 1}, 'dominfo': {'a074f327-d0d2-445a-af76-60a5c69fbc29': {'status': 'Active', 'diskfree': '899762094080', 'alerts': [], 'disktotal': '977827528704'}}}
>Thread-132::DEBUG::2012-08-15 11:11:05,168::task::568::TaskManager.Task::(_updateState) Task=`af8d7709-102d-444a-b0e9-ae0c3f148cda`::moving from state preparing -> state finished
>Thread-132::DEBUG::2012-08-15 11:11:05,168::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1': < ResourceRef 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1', isValid: 'True' obj: 'None'>}
>Thread-132::DEBUG::2012-08-15 11:11:05,168::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-132::DEBUG::2012-08-15 11:11:05,168::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1'
>Thread-132::DEBUG::2012-08-15 11:11:05,169::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1' (0 active users)
>Thread-132::DEBUG::2012-08-15 11:11:05,169::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1' is free, finding out if anyone is waiting for it.
>Thread-132::DEBUG::2012-08-15 11:11:05,169::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1', Clearing records.
>Thread-132::DEBUG::2012-08-15 11:11:05,169::task::957::TaskManager.Task::(_decref) Task=`af8d7709-102d-444a-b0e9-ae0c3f148cda`::ref 0 aborting False
>Thread-133::DEBUG::2012-08-15 11:11:06,997::task::568::TaskManager.Task::(_updateState) Task=`8322a904-e945-4549-8393-d4bd88f5214a`::moving from state init -> state preparing
>Thread-133::INFO::2012-08-15 11:11:06,997::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-133::INFO::2012-08-15 11:11:06,998::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'a074f327-d0d2-445a-af76-60a5c69fbc29': {'delay': '0.00620889663696', 'lastCheck': 1345018259.117734, 'code': 0, 'valid': True}}
>Thread-133::DEBUG::2012-08-15 11:11:06,998::task::1151::TaskManager.Task::(prepare) Task=`8322a904-e945-4549-8393-d4bd88f5214a`::finished: {'a074f327-d0d2-445a-af76-60a5c69fbc29': {'delay': '0.00620889663696', 'lastCheck': 1345018259.117734, 'code': 0, 'valid': True}}
>Thread-133::DEBUG::2012-08-15 11:11:06,998::task::568::TaskManager.Task::(_updateState) Task=`8322a904-e945-4549-8393-d4bd88f5214a`::moving from state preparing -> state finished
>Thread-133::DEBUG::2012-08-15 11:11:06,998::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-133::DEBUG::2012-08-15 11:11:06,998::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-133::DEBUG::2012-08-15 11:11:06,998::task::957::TaskManager.Task::(_decref) Task=`8322a904-e945-4549-8393-d4bd88f5214a`::ref 0 aborting False
>Thread-139::DEBUG::2012-08-15 11:11:15,311::BindingXMLRPC::160::vds::(wrapper) [10.35.1.234]
>Thread-139::DEBUG::2012-08-15 11:11:15,311::task::568::TaskManager.Task::(_updateState) Task=`a29df3a0-25ea-4402-82bd-53203c884247`::moving from state init -> state preparing
>Thread-139::INFO::2012-08-15 11:11:15,311::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='22f91e5e-fa21-4975-8fac-f6ab5191cab1', options=None)
>Thread-139::INFO::2012-08-15 11:11:15,312::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 1}}
>Thread-139::DEBUG::2012-08-15 11:11:15,312::task::1151::TaskManager.Task::(prepare) Task=`a29df3a0-25ea-4402-82bd-53203c884247`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 1}}
>Thread-139::DEBUG::2012-08-15 11:11:15,312::task::568::TaskManager.Task::(_updateState) Task=`a29df3a0-25ea-4402-82bd-53203c884247`::moving from state preparing -> state finished
>Thread-139::DEBUG::2012-08-15 11:11:15,312::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-139::DEBUG::2012-08-15 11:11:15,312::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-139::DEBUG::2012-08-15 11:11:15,312::task::957::TaskManager.Task::(_decref) Task=`a29df3a0-25ea-4402-82bd-53203c884247`::ref 0 aborting False
>Thread-140::DEBUG::2012-08-15 11:11:15,317::BindingXMLRPC::160::vds::(wrapper) [10.35.1.234]
>Thread-140::DEBUG::2012-08-15 11:11:15,317::task::568::TaskManager.Task::(_updateState) Task=`ab4dbd6a-c9f2-4ec4-9bee-cf05a0b9d056`::moving from state init -> state preparing
>Thread-140::INFO::2012-08-15 11:11:15,317::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='22f91e5e-fa21-4975-8fac-f6ab5191cab1', options=None)
>Thread-140::DEBUG::2012-08-15 11:11:15,318::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1`ReqID=`fc508d44-dff4-4eaf-8fb2-771428dc3978`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-140::DEBUG::2012-08-15 11:11:15,318::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1' for lock type 'shared'
>Thread-140::DEBUG::2012-08-15 11:11:15,318::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1' is free. Now locking as 'shared' (1 active user)
>Thread-140::DEBUG::2012-08-15 11:11:15,318::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1`ReqID=`fc508d44-dff4-4eaf-8fb2-771428dc3978`::Granted request
>Thread-140::DEBUG::2012-08-15 11:11:15,318::task::794::TaskManager.Task::(resourceAcquired) Task=`ab4dbd6a-c9f2-4ec4-9bee-cf05a0b9d056`::_resourcesAcquired: Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1 (shared)
>Thread-140::DEBUG::2012-08-15 11:11:15,319::task::957::TaskManager.Task::(_decref) Task=`ab4dbd6a-c9f2-4ec4-9bee-cf05a0b9d056`::ref 1 aborting False
>Thread-140::INFO::2012-08-15 11:11:15,321::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': 'a074f327-d0d2-445a-af76-60a5c69fbc29', 'name': 'dc2', 'version': '3', 'domains': 'a074f327-d0d2-445a-af76-60a5c69fbc29:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 1}, 'dominfo': {'a074f327-d0d2-445a-af76-60a5c69fbc29': {'status': 'Active', 'diskfree': '899762094080', 'alerts': [], 'disktotal': '977827528704'}}}
>Thread-140::DEBUG::2012-08-15 11:11:15,322::task::1151::TaskManager.Task::(prepare) Task=`ab4dbd6a-c9f2-4ec4-9bee-cf05a0b9d056`::finished: {'info': {'spm_id': 1, 'master_uuid': 'a074f327-d0d2-445a-af76-60a5c69fbc29', 'name': 'dc2', 'version': '3', 'domains': 'a074f327-d0d2-445a-af76-60a5c69fbc29:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 1}, 'dominfo': {'a074f327-d0d2-445a-af76-60a5c69fbc29': {'status': 'Active', 'diskfree': '899762094080', 'alerts': [], 'disktotal': '977827528704'}}}
>Thread-140::DEBUG::2012-08-15 11:11:15,322::task::568::TaskManager.Task::(_updateState) Task=`ab4dbd6a-c9f2-4ec4-9bee-cf05a0b9d056`::moving from state preparing -> state finished
>Thread-140::DEBUG::2012-08-15 11:11:15,322::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1': < ResourceRef 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1', isValid: 'True' obj: 'None'>}
>Thread-140::DEBUG::2012-08-15 11:11:15,322::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-140::DEBUG::2012-08-15 11:11:15,322::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1'
>Thread-140::DEBUG::2012-08-15 11:11:15,322::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1' (0 active users)
>Thread-140::DEBUG::2012-08-15 11:11:15,323::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1' is free, finding out if anyone is waiting for it.
>Thread-140::DEBUG::2012-08-15 11:11:15,323::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.22f91e5e-fa21-4975-8fac-f6ab5191cab1', Clearing records.
>Thread-140::DEBUG::2012-08-15 11:11:15,323::task::957::TaskManager.Task::(_decref) Task=`ab4dbd6a-c9f2-4ec4-9bee-cf05a0b9d056`::ref 0 aborting False
>Thread-141::DEBUG::2012-08-15 11:11:17,091::task::568::TaskManager.Task::(_updateState) Task=`a18991ad-eb71-4f0f-83ae-030aaef251f8`::moving from state init -> state preparing
>Thread-141::INFO::2012-08-15 11:11:17,092::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-141::INFO::2012-08-15 11:11:17,092::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'a074f327-d0d2-445a-af76-60a5c69fbc29': {'delay': '0.00675582885742', 'lastCheck': 1345018269.130614, 'code': 0, 'valid': True}}
>Thread-141::DEBUG::2012-08-15 11:11:17,092::task::1151::TaskManager.Task::(prepare) Task=`a18991ad-eb71-4f0f-83ae-030aaef251f8`::finished: {'a074f327-d0d2-445a-af76-60a5c69fbc29': {'delay': '0.00675582885742', 'lastCheck': 1345018269.130614, 'code': 0, 'valid': True}}
>Thread-141::DEBUG::2012-08-15 11:11:17,092::task::568::TaskManager.Task::(_updateState) Task=`a18991ad-eb71-4f0f-83ae-030aaef251f8`::moving from state preparing -> state finished
>Thread-141::DEBUG::2012-08-15 11:11:17,092::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-141::DEBUG::2012-08-15 11:11:17,092::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-141::DEBUG::2012-08-15 11:11:17,092::task::957::TaskManager.Task::(_decref) Task=`a18991ad-eb71-4f0f-83ae-030aaef251f8`::ref 0 aborting False
>MainThread::INFO::2012-08-15 11:11:34,201::vmChannels::135::vds::(stop) VM channels listener was stopped.
>MainThread::DEBUG::2012-08-15 11:11:34,202::task::568::TaskManager.Task::(_updateState) Task=`917d45aa-cb55-4ec3-bf90-cad671ac91b4`::moving from state init -> state preparing
>MainThread::INFO::2012-08-15 11:11:34,202::logUtils::37::dispatcher::(wrapper) Run and protect: prepareForShutdown(options=None)
>Thread-11::DEBUG::2012-08-15 11:11:34,202::storageServer::617::ConnectionMonitor::(_monitorConnections) Monitoring stopped
>Thread-37::DEBUG::2012-08-15 11:11:34,250::domainMonitor::182::Storage.DomainMonitor::(_monitorDomain) Monitorg for domain a074f327-d0d2-445a-af76-60a5c69fbc29 is stopping
>Thread-37::INFO::2012-08-15 11:11:34,250::safelease::183::SANLock::(releaseHostId) Releasing host id for domain a074f327-d0d2-445a-af76-60a5c69fbc29 (id: 1)
>Thread-37::DEBUG::2012-08-15 11:11:34,250::domainMonitor::191::Storage.DomainMonitor::(_monitorDomain) Unable to release the host id 1 for the domain a074f327-d0d2-445a-af76-60a5c69fbc29
>Traceback (most recent call last):
>  File "/usr/share/vdsm/storage/domainMonitor.py", line 188, in _monitorDomain
>    domain.releaseHostId(hostId, unused=True)
>  File "/usr/share/vdsm/storage/sd.py", line 426, in releaseHostId
>    self._clusterLock.releaseHostId(hostId, async, unused)
>  File "/usr/share/vdsm/storage/safelease.py", line 190, in releaseHostId
>    raise se.ReleaseHostIdFailure(self._sdUUID, e)
>ReleaseHostIdFailure: Cannot release host id: ('a074f327-d0d2-445a-af76-60a5c69fbc29', SanlockException(16, 'Sanlock lockspace remove failure', 'Device or resource busy'))
>MainThread::DEBUG::2012-08-15 11:11:34,251::taskManager::80::TaskManager::(prepareForShutdown) Request to stop all tasks
>MainThread::INFO::2012-08-15 11:11:34,251::logUtils::39::dispatcher::(wrapper) Run and protect: prepareForShutdown, Return response: None
>MainThread::DEBUG::2012-08-15 11:11:34,251::task::1151::TaskManager.Task::(prepare) Task=`917d45aa-cb55-4ec3-bf90-cad671ac91b4`::finished: None
>MainThread::DEBUG::2012-08-15 11:11:34,251::task::568::TaskManager.Task::(_updateState) Task=`917d45aa-cb55-4ec3-bf90-cad671ac91b4`::moving from state preparing -> state finished
>MainThread::DEBUG::2012-08-15 11:11:34,251::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>MainThread::DEBUG::2012-08-15 11:11:34,251::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>MainThread::DEBUG::2012-08-15 11:11:34,252::task::957::TaskManager.Task::(_decref) Task=`917d45aa-cb55-4ec3-bf90-cad671ac91b4`::ref 0 aborting False
>MainThread::INFO::2012-08-15 11:11:34,252::vdsm::76::vds::(run) VDSM main thread ended. Waiting for 13 other threads...
>MainThread::INFO::2012-08-15 11:11:34,252::vdsm::79::vds::(run) <_MainThread(MainThread, started 140163402516224)>
>MainThread::INFO::2012-08-15 11:11:34,252::vdsm::79::vds::(run) <Thread(libvirtEventLoop, started daemon 140163325499136)>
>MainThread::INFO::2012-08-15 11:11:34,252::vdsm::79::vds::(run) <KsmMonitorThread(KsmMonitor, started daemon 140162468136704)>
>MainThread::INFO::2012-08-15 11:11:34,252::vdsm::79::vds::(run) <WorkerThread(Thread-3, started daemon 140163195557632)>
>MainThread::INFO::2012-08-15 11:11:34,252::vdsm::79::vds::(run) <WorkerThread(Thread-2, started daemon 140163206047488)>
>MainThread::INFO::2012-08-15 11:11:34,252::vdsm::79::vds::(run) <WorkerThread(1633319d-222b-41d0-808c-55ac47143904, started daemon 140163216537344)>
>MainThread::INFO::2012-08-15 11:11:34,253::vdsm::79::vds::(run) <WorkerThread(Thread-10, started daemon 140162916919040)>
>MainThread::INFO::2012-08-15 11:11:34,253::vdsm::79::vds::(run) <WorkerThread(Thread-9, started daemon 140162927408896)>
>MainThread::INFO::2012-08-15 11:11:34,253::vdsm::79::vds::(run) <WorkerThread(Thread-8, started daemon 140162937898752)>
>MainThread::INFO::2012-08-15 11:11:34,253::vdsm::79::vds::(run) <WorkerThread(Thread-6, started daemon 140162958878464)>
>MainThread::INFO::2012-08-15 11:11:34,253::vdsm::79::vds::(run) <WorkerThread(Thread-5, started daemon 140162969368320)>
>MainThread::INFO::2012-08-15 11:11:34,253::vdsm::79::vds::(run) <WorkerThread(Thread-4, started daemon 140163185067776)>
>MainThread::INFO::2012-08-15 11:11:34,253::vmChannels::135::vds::(stop) VM channels listener was stopped.
>MainThread::INFO::2012-08-15 11:11:34,253::vdsm::79::vds::(run) <Listener(VM Channels Listener, started daemon 140162447156992)>
>MainThread::INFO::2012-08-15 11:11:34,253::vdsm::79::vds::(run) <WorkerThread(Thread-7, started daemon 140162948388608)>

Actions: View

Attachments on bug 848298: 604544 | 604545