MainThread::INFO::2012-05-16 18:04:48,399::vdsm::70::vds::(run) I am the actual vdsm 4.9-0
MainThread::DEBUG::2012-05-16 18:04:48,566::resourceManager::379::ResourceManager::(registerNamespace) Registering namespace 'Storage'
MainThread::DEBUG::2012-05-16 18:04:48,566::threadPool::45::Misc.ThreadPool::(__init__) Enter - numThreads: 10.0, waitTimeout: 3, maxTasks: 500.0
MainThread::DEBUG::2012-05-16 18:04:48,603::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /bin/kill -9 1883' (cwd None)
MainThread::DEBUG::2012-05-16 18:04:48,648::__init__::1249::Storage.Misc.excCmd::(_log) FAILED: <err> = 'kill 1883: No such process\n'; <rc> = 1
MainThread::DEBUG::2012-05-16 18:04:48,648::supervdsm::91::SuperVdsmProxy::(_launchSupervdsm) Launching Super Vdsm
MainThread::DEBUG::2012-05-16 18:04:48,648::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /usr/bin/python /usr/share/vdsm/supervdsmServer.py 9d8a7a47-6807-4cde-9292-1ad27f070104 5074' (cwd None)
MainThread::DEBUG::2012-05-16 18:04:48,794::supervdsmServer::279::SuperVdsm.Server::(main) Making sure I'm root
MainThread::DEBUG::2012-05-16 18:04:48,794::supervdsmServer::283::SuperVdsm.Server::(main) Parsing cmd args
MainThread::DEBUG::2012-05-16 18:04:48,795::supervdsmServer::286::SuperVdsm.Server::(main) Creating PID file
MainThread::DEBUG::2012-05-16 18:04:48,795::supervdsmServer::290::SuperVdsm.Server::(main) Cleaning old socket
MainThread::DEBUG::2012-05-16 18:04:48,795::supervdsmServer::294::SuperVdsm.Server::(main) Setting up keep alive thread
MainThread::DEBUG::2012-05-16 18:04:48,795::supervdsmServer::300::SuperVdsm.Server::(main) Creating remote object manager
MainThread::DEBUG::2012-05-16 18:04:48,796::supervdsmServer::311::SuperVdsm.Server::(main) Started serving super vdsm object
MainThread::DEBUG::2012-05-16 18:04:50,657::supervdsm::113::SuperVdsmProxy::(_connect) Trying to connect to Super Vdsm
MainThread::DEBUG::2012-05-16 18:04:50,665::supervdsm::84::SuperVdsmProxy::(__init__) Connected to Super Vdsm
MainThread::DEBUG::2012-05-16 18:04:50,667::multipath::102::Storage.Multipath::(isEnabled) Current revision of multipath.conf detected, preserving
MainThread::DEBUG::2012-05-16 18:04:50,667::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/lvm dumpconfig global/locking_type' (cwd None)
MainThread::DEBUG::2012-05-16 18:04:50,713::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
MainThread::DEBUG::2012-05-16 18:04:50,714::lvm::333::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' got the operation mutex
MainThread::DEBUG::2012-05-16 18:04:50,716::__init__::1249::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 = [ \\"a%3600605b003b86620166a1ddb0bfa15b7%\\", \\"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-05-16 18:04:50,883::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
MainThread::DEBUG::2012-05-16 18:04:50,884::lvm::356::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' released the operation mutex
MainThread::DEBUG::2012-05-16 18:04:50,884::lvm::366::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
MainThread::DEBUG::2012-05-16 18:04:50,885::__init__::1249::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 = [ \\"a%3600605b003b86620166a1ddb0bfa15b7%\\", \\"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-05-16 18:04:50,944::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
MainThread::DEBUG::2012-05-16 18:04:50,946::lvm::393::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
MainThread::DEBUG::2012-05-16 18:04:50,947::__init__::1249::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 = [ \\"a%3600605b003b86620166a1ddb0bfa15b7%\\", \\"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-05-16 18:04:51,008::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-12::DEBUG::2012-05-16 18:04:51,013::misc::1057::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
MainThread::INFO::2012-05-16 18:04:51,015::dispatcher::95::Storage.Dispatcher::(__init__) Starting StorageDispatcher...
Thread-12::DEBUG::2012-05-16 18:04:51,015::misc::1059::SamplingMethod::(__call__) Got in to sampling method
Thread-12::DEBUG::2012-05-16 18:04:51,016::misc::1057::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
Thread-12::DEBUG::2012-05-16 18:04:51,017::misc::1059::SamplingMethod::(__call__) Got in to sampling method
Thread-12::DEBUG::2012-05-16 18:04:51,017::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
MainThread::DEBUG::2012-05-16 18:04:51,027::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/pgrep -xf ksmd' (cwd None)
Thread-12::DEBUG::2012-05-16 18:04:51,036::__init__::1249::Storage.Misc.excCmd::(_log) FAILED: <err> = 'iscsiadm: No session found.\n'; <rc> = 21
Thread-12::DEBUG::2012-05-16 18:04:51,037::misc::1067::SamplingMethod::(__call__) Returning last result
MainThread::DEBUG::2012-05-16 18:04:51,051::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
MainThread::INFO::2012-05-16 18:04:51,052::vmChannels::139::vds::(settimeout) Setting channels' timeout to 30 seconds.
VM Channels Listener::INFO::2012-05-16 18:04:51,053::vmChannels::127::vds::(run) Starting VM channels listener thread.
Thread-12::DEBUG::2012-05-16 18:04:52,957::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/multipath' (cwd None)
Thread-12::DEBUG::2012-05-16 18:04:52,977::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-12::DEBUG::2012-05-16 18:04:52,978::lvm::474::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-12::DEBUG::2012-05-16 18:04:52,978::lvm::476::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-12::DEBUG::2012-05-16 18:04:52,979::lvm::486::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
Thread-12::DEBUG::2012-05-16 18:04:52,979::lvm::488::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
Thread-12::DEBUG::2012-05-16 18:04:52,980::lvm::507::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-12::DEBUG::2012-05-16 18:04:52,980::lvm::509::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-12::DEBUG::2012-05-16 18:04:52,980::misc::1067::SamplingMethod::(__call__) Returning last result
Thread-12::DEBUG::2012-05-16 18:04:52,981::hsm::360::Storage.HSM::(__cleanStorageRepository) Started cleaning storage repository at '/rhev/data-center'
Thread-12::DEBUG::2012-05-16 18:04:52,988::hsm::392::Storage.HSM::(__cleanStorageRepository) White list: ['/rhev/data-center/hsm-tasks', '/rhev/data-center/hsm-tasks/*', '/rhev/data-center/mnt']
Thread-12::DEBUG::2012-05-16 18:04:52,989::hsm::393::Storage.HSM::(__cleanStorageRepository) Mount list: []
Thread-12::DEBUG::2012-05-16 18:04:52,989::hsm::395::Storage.HSM::(__cleanStorageRepository) Cleaning leftovers
Thread-12::DEBUG::2012-05-16 18:04:52,990::hsm::438::Storage.HSM::(__cleanStorageRepository) Finished cleaning storage repository at '/rhev/data-center'
MainThread::INFO::2012-05-16 18:06:17,346::vmChannels::135::vds::(stop) VM channels listener was stopped.
MainThread::DEBUG::2012-05-16 18:06:17,347::task::588::TaskManager.Task::(_updateState) Task=`85027ca7-cb1d-4b6c-87d0-559d26aa52ca`::moving from state init -> state preparing
MainThread::INFO::2012-05-16 18:06:17,348::logUtils::37::dispatcher::(wrapper) Run and protect: prepareForShutdown(options=None)
Thread-11::DEBUG::2012-05-16 18:06:17,348::storageServer::610::ConnectionMonitor::(_monitorConnections) Monitoring stopped
MainThread::DEBUG::2012-05-16 18:06:17,388::taskManager::80::TaskManager::(prepareForShutdown) Request to stop all tasks
MainThread::INFO::2012-05-16 18:06:17,388::logUtils::39::dispatcher::(wrapper) Run and protect: prepareForShutdown, Return response: None
MainThread::DEBUG::2012-05-16 18:06:17,388::task::1172::TaskManager.Task::(prepare) Task=`85027ca7-cb1d-4b6c-87d0-559d26aa52ca`::finished: None
MainThread::DEBUG::2012-05-16 18:06:17,389::task::588::TaskManager.Task::(_updateState) Task=`85027ca7-cb1d-4b6c-87d0-559d26aa52ca`::moving from state preparing -> state finished
MainThread::DEBUG::2012-05-16 18:06:17,389::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
MainThread::DEBUG::2012-05-16 18:06:17,389::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
MainThread::DEBUG::2012-05-16 18:06:17,389::task::978::TaskManager.Task::(_decref) Task=`85027ca7-cb1d-4b6c-87d0-559d26aa52ca`::ref 0 aborting False
MainThread::INFO::2012-05-16 18:06:17,389::vdsm::75::vds::(run) VDSM main thread ended. Waiting for 13 other threads...
MainThread::INFO::2012-05-16 18:06:17,390::vdsm::78::vds::(run) <_MainThread(MainThread, started 140580310492928)>
MainThread::INFO::2012-05-16 18:06:17,390::vdsm::78::vds::(run) <Thread(libvirtEventLoop, started daemon 140580226758400)>
MainThread::INFO::2012-05-16 18:06:17,390::vdsm::78::vds::(run) <KsmMonitorThread(KsmMonitor, started daemon 140579472123648)>
MainThread::INFO::2012-05-16 18:06:17,390::vdsm::78::vds::(run) <WorkerThread(Thread-1, started daemon 140580195383040)>
MainThread::INFO::2012-05-16 18:06:17,390::vdsm::78::vds::(run) <WorkerThread(Thread-10, started daemon 140579505694464)>
MainThread::INFO::2012-05-16 18:06:17,391::vdsm::78::vds::(run) <WorkerThread(Thread-5, started daemon 140580092888832)>
MainThread::INFO::2012-05-16 18:06:17,391::vdsm::78::vds::(run) <WorkerThread(Thread-9, started daemon 140579514087168)>
MainThread::INFO::2012-05-16 18:06:17,391::vdsm::78::vds::(run) <WorkerThread(Thread-3, started daemon 140580109674240)>
MainThread::INFO::2012-05-16 18:06:17,391::vdsm::78::vds::(run) <WorkerThread(Thread-6, started daemon 140580084496128)>
MainThread::INFO::2012-05-16 18:06:17,391::vdsm::78::vds::(run) <WorkerThread(Thread-2, started daemon 140580118066944)>
MainThread::INFO::2012-05-16 18:06:17,392::vdsm::78::vds::(run) <WorkerThread(Thread-7, started daemon 140580076103424)>
MainThread::INFO::2012-05-16 18:06:17,392::vdsm::78::vds::(run) <WorkerThread(Thread-8, started daemon 140580067710720)>
MainThread::INFO::2012-05-16 18:06:17,392::vmChannels::135::vds::(stop) VM channels listener was stopped.
MainThread::INFO::2012-05-16 18:06:17,392::vdsm::78::vds::(run) <Listener(VM Channels Listener, started daemon 140578977216256)>
MainThread::INFO::2012-05-16 18:06:17,392::vdsm::78::vds::(run) <WorkerThread(Thread-4, started daemon 140580101281536)>
MainThread::INFO::2012-05-16 18:21:43,856::vdsm::70::vds::(run) I am the actual vdsm 4.9-0
MainThread::DEBUG::2012-05-16 18:21:44,068::resourceManager::379::ResourceManager::(registerNamespace) Registering namespace 'Storage'
MainThread::DEBUG::2012-05-16 18:21:44,068::threadPool::45::Misc.ThreadPool::(__init__) Enter - numThreads: 10.0, waitTimeout: 3, maxTasks: 500.0
MainThread::DEBUG::2012-05-16 18:21:44,134::supervdsm::103::SuperVdsmProxy::(_killSupervdsm) Could not kill old Super Vdsm [Errno 2] No such file or directory: '/var/run/vdsm/svdsm.pid'
MainThread::DEBUG::2012-05-16 18:21:44,135::supervdsm::91::SuperVdsmProxy::(_launchSupervdsm) Launching Super Vdsm
MainThread::DEBUG::2012-05-16 18:21:44,135::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /usr/bin/python /usr/share/vdsm/supervdsmServer.py 3f6a965a-1b20-4df6-a077-69344a15ca64 1888' (cwd None)
MainThread::DEBUG::2012-05-16 18:21:44,288::supervdsmServer::279::SuperVdsm.Server::(main) Making sure I'm root
MainThread::DEBUG::2012-05-16 18:21:44,289::supervdsmServer::283::SuperVdsm.Server::(main) Parsing cmd args
MainThread::DEBUG::2012-05-16 18:21:44,289::supervdsmServer::286::SuperVdsm.Server::(main) Creating PID file
MainThread::DEBUG::2012-05-16 18:21:44,289::supervdsmServer::290::SuperVdsm.Server::(main) Cleaning old socket
MainThread::DEBUG::2012-05-16 18:21:44,289::supervdsmServer::294::SuperVdsm.Server::(main) Setting up keep alive thread
MainThread::DEBUG::2012-05-16 18:21:44,290::supervdsmServer::300::SuperVdsm.Server::(main) Creating remote object manager
MainThread::DEBUG::2012-05-16 18:21:44,291::supervdsmServer::311::SuperVdsm.Server::(main) Started serving super vdsm object
MainThread::DEBUG::2012-05-16 18:21:46,144::supervdsm::113::SuperVdsmProxy::(_connect) Trying to connect to Super Vdsm
MainThread::DEBUG::2012-05-16 18:21:46,152::supervdsm::84::SuperVdsmProxy::(__init__) Connected to Super Vdsm
MainThread::DEBUG::2012-05-16 18:21:46,153::multipath::102::Storage.Multipath::(isEnabled) Current revision of multipath.conf detected, preserving
MainThread::DEBUG::2012-05-16 18:21:46,153::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/lvm dumpconfig global/locking_type' (cwd None)
MainThread::DEBUG::2012-05-16 18:21:46,198::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
MainThread::DEBUG::2012-05-16 18:21:46,199::lvm::333::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' got the operation mutex
MainThread::DEBUG::2012-05-16 18:21:46,201::__init__::1249::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 = [ \\"a%3600605b003b86620166a1ddb0bfa15b7%\\", \\"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-05-16 18:21:46,288::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
MainThread::DEBUG::2012-05-16 18:21:46,289::lvm::356::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' released the operation mutex
MainThread::DEBUG::2012-05-16 18:21:46,289::lvm::366::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
MainThread::DEBUG::2012-05-16 18:21:46,290::__init__::1249::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 = [ \\"a%3600605b003b86620166a1ddb0bfa15b7%\\", \\"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-05-16 18:21:46,346::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
MainThread::DEBUG::2012-05-16 18:21:46,348::lvm::393::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
MainThread::DEBUG::2012-05-16 18:21:46,349::__init__::1249::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 = [ \\"a%3600605b003b86620166a1ddb0bfa15b7%\\", \\"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-05-16 18:21:46,403::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-12::DEBUG::2012-05-16 18:21:46,408::misc::1057::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
MainThread::INFO::2012-05-16 18:21:46,410::dispatcher::95::Storage.Dispatcher::(__init__) Starting StorageDispatcher...
Thread-12::DEBUG::2012-05-16 18:21:46,410::misc::1059::SamplingMethod::(__call__) Got in to sampling method
Thread-12::DEBUG::2012-05-16 18:21:46,411::misc::1057::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
Thread-12::DEBUG::2012-05-16 18:21:46,412::misc::1059::SamplingMethod::(__call__) Got in to sampling method
Thread-12::DEBUG::2012-05-16 18:21:46,412::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
MainThread::DEBUG::2012-05-16 18:21:46,423::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/pgrep -xf ksmd' (cwd None)
Thread-12::DEBUG::2012-05-16 18:21:46,433::__init__::1249::Storage.Misc.excCmd::(_log) FAILED: <err> = 'iscsiadm: No session found.\n'; <rc> = 21
Thread-12::DEBUG::2012-05-16 18:21:46,434::misc::1067::SamplingMethod::(__call__) Returning last result
MainThread::DEBUG::2012-05-16 18:21:46,446::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
MainThread::INFO::2012-05-16 18:21:46,448::vmChannels::139::vds::(settimeout) Setting channels' timeout to 30 seconds.
VM Channels Listener::INFO::2012-05-16 18:21:46,449::vmChannels::127::vds::(run) Starting VM channels listener thread.
Thread-12::DEBUG::2012-05-16 18:21:48,368::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/multipath' (cwd None)
Thread-12::DEBUG::2012-05-16 18:21:48,393::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-12::DEBUG::2012-05-16 18:21:48,393::lvm::474::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-12::DEBUG::2012-05-16 18:21:48,394::lvm::476::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-12::DEBUG::2012-05-16 18:21:48,394::lvm::486::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
Thread-12::DEBUG::2012-05-16 18:21:48,395::lvm::488::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
Thread-12::DEBUG::2012-05-16 18:21:48,395::lvm::507::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-12::DEBUG::2012-05-16 18:21:48,396::lvm::509::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-12::DEBUG::2012-05-16 18:21:48,396::misc::1067::SamplingMethod::(__call__) Returning last result
Thread-12::DEBUG::2012-05-16 18:21:48,396::hsm::360::Storage.HSM::(__cleanStorageRepository) Started cleaning storage repository at '/rhev/data-center'
Thread-12::DEBUG::2012-05-16 18:21:48,405::hsm::392::Storage.HSM::(__cleanStorageRepository) White list: ['/rhev/data-center/hsm-tasks', '/rhev/data-center/hsm-tasks/*', '/rhev/data-center/mnt']
Thread-12::DEBUG::2012-05-16 18:21:48,405::hsm::393::Storage.HSM::(__cleanStorageRepository) Mount list: []
Thread-12::DEBUG::2012-05-16 18:21:48,405::hsm::395::Storage.HSM::(__cleanStorageRepository) Cleaning leftovers
Thread-12::DEBUG::2012-05-16 18:21:48,407::hsm::438::Storage.HSM::(__cleanStorageRepository) Finished cleaning storage repository at '/rhev/data-center'
Thread-14::DEBUG::2012-05-16 18:22:30,588::BindingXMLRPC::864::vds::(wrapper) client [9.181.129.153]::call getCapabilities with () {} flowID [4b4e81f4]
Thread-14::DEBUG::2012-05-16 18:22:30,844::__init__::1249::Storage.Misc.excCmd::(_log) '/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" qemu-kvm' (cwd None)
Thread-14::DEBUG::2012-05-16 18:22:30,886::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-14::DEBUG::2012-05-16 18:22:30,887::__init__::1249::Storage.Misc.excCmd::(_log) '/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" qemu-img' (cwd None)
Thread-14::DEBUG::2012-05-16 18:22:30,925::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-14::DEBUG::2012-05-16 18:22:30,926::__init__::1249::Storage.Misc.excCmd::(_log) '/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" vdsm' (cwd None)
Thread-14::DEBUG::2012-05-16 18:22:30,965::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-14::DEBUG::2012-05-16 18:22:30,966::__init__::1249::Storage.Misc.excCmd::(_log) '/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" spice-server' (cwd None)
Thread-14::DEBUG::2012-05-16 18:22:30,998::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-14::DEBUG::2012-05-16 18:22:30,998::__init__::1249::Storage.Misc.excCmd::(_log) '/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" libvirt' (cwd None)
Thread-14::DEBUG::2012-05-16 18:22:31,057::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-14::DEBUG::2012-05-16 18:22:31,206::BindingXMLRPC::870::vds::(wrapper) return getCapabilities with {'status': {'message': 'Done', 'code': 0}, 'info': {'HBAInventory': {'iSCSI': [{'InitiatorName': 'iqn.1994-05.com.redhat:f1b658ea7af8'}], 'FC': []}, 'packages2': {'kernel': {'release': '2.fc16.x86_64', 'buildtime': 1330952139.0, 'version': '3.2.9'}, 'spice-server': {'release': '1.fc16', 'buildtime': '1327339129', 'version': '0.10.1'}, 'vdsm': {'release': '0.183.git107644d.fc16.shuming1336622293', 'buildtime': '1336622307', 'version': '4.9.6'}, 'qemu-kvm': {'release': '4.fc16', 'buildtime': '1327954752', 'version': '0.15.1'}, 'libvirt': {'release': '1.fc17', 'buildtime': '1335562267', 'version': '0.9.11.3'}, 'qemu-img': {'release': '4.fc16', 'buildtime': '1327954752', 'version': '0.15.1'}}, 'cpuModel': 'Intel(R) Xeon(R) CPU           X5650  @ 2.67GHz', 'hooks': {}, 'vmTypes': ['kvm'], 'supportedProtocols': ['2.2', '2.3'], 'networks': {}, 'uuid': '36D82702-FBFD-11E0-9A46-E41F13BE8FA8_00:00:C9:E5:A0:6E', 'lastClientIface': 'ovirtmgmt', 'nics': {'p2p1': {'hwaddr': '00:00:C9:E5:A0:6E', 'netmask': '', 'speed': 0, 'addr': '', 'mtu': '1500'}, 'p2p2': {'hwaddr': '00:00:C9:E5:A0:72', 'netmask': '', 'speed': 0, 'addr': '', 'mtu': '1500'}, 'eth1': {'hwaddr': 'E4:1F:13:BE:8F:AA', 'netmask': '', 'speed': 0, 'addr': '', 'mtu': '1500'}, 'eth0': {'hwaddr': 'E4:1F:13:BE:8F:A8', 'netmask': '', 'speed': 100, 'addr': '', 'mtu': '1500'}}, 'software_revision': '0', 'management_ip': '', 'clusterLevels': ['3.0', '3.1'], 'cpuFlags': u'fpu,vme,de,pse,tsc,msr,pae,mce,cx8,apic,sep,mtrr,pge,mca,cmov,pat,pse36,clflush,dts,acpi,mmx,fxsr,sse,sse2,ss,ht,tm,pbe,syscall,nx,pdpe1gb,rdtscp,lm,constant_tsc,arch_perfmon,pebs,bts,rep_good,nopl,xtopology,nonstop_tsc,aperfmperf,pni,pclmulqdq,dtes64,monitor,ds_cpl,vmx,smx,est,tm2,ssse3,cx16,xtpr,pdcm,pcid,dca,sse4_1,sse4_2,popcnt,aes,lahf_lm,arat,epb,dts,tpr_shadow,vnmi,flexpriority,ept,vpid,model_coreduo,model_Conroe', 'ISCSIInitiatorName': 'iqn.1994-05.com.redhat:f1b658ea7af8', 'memSize': '72486', '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.9', 'cpuSpeed': '1596.000', 'cpuSockets': '2', 'vlans': {}, 'cpuCores': '12', 'kvmEnabled': 'true', 'guestOverhead': '65', 'supportedRHEVMs': ['3.0'], 'version_name': 'Snow Man', 'emulatedMachines': [u'pc-0.14', u'pc', u'fedora-13', u'pc-0.13', u'pc-0.12', u'pc-0.11', u'pc-0.10', u'isapc', u'pc-0.14', u'pc', u'fedora-13', u'pc-0.13', u'pc-0.12', u'pc-0.11', u'pc-0.10', u'isapc'], 'operatingSystem': {'release': '1', 'version': '16', 'name': 'oVirt Node'}, 'lastClient': '0.0.0.0'}}
Thread-15::DEBUG::2012-05-16 18:22:31,259::BindingXMLRPC::864::vds::(wrapper) client [9.181.129.153]::call getCapabilities with () {} flowID [2fb2ec2e]
Thread-15::DEBUG::2012-05-16 18:22:31,280::__init__::1249::Storage.Misc.excCmd::(_log) '/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" qemu-kvm' (cwd None)
Thread-15::DEBUG::2012-05-16 18:22:31,305::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-15::DEBUG::2012-05-16 18:22:31,306::__init__::1249::Storage.Misc.excCmd::(_log) '/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" qemu-img' (cwd None)
Thread-15::DEBUG::2012-05-16 18:22:31,328::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-15::DEBUG::2012-05-16 18:22:31,328::__init__::1249::Storage.Misc.excCmd::(_log) '/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" vdsm' (cwd None)
Thread-15::DEBUG::2012-05-16 18:22:31,352::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-15::DEBUG::2012-05-16 18:22:31,353::__init__::1249::Storage.Misc.excCmd::(_log) '/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" spice-server' (cwd None)
Thread-15::DEBUG::2012-05-16 18:22:31,373::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-15::DEBUG::2012-05-16 18:22:31,374::__init__::1249::Storage.Misc.excCmd::(_log) '/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" libvirt' (cwd None)
Thread-15::DEBUG::2012-05-16 18:22:31,395::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-15::DEBUG::2012-05-16 18:22:31,396::BindingXMLRPC::870::vds::(wrapper) return getCapabilities with {'status': {'message': 'Done', 'code': 0}, 'info': {'HBAInventory': {'iSCSI': [{'InitiatorName': 'iqn.1994-05.com.redhat:f1b658ea7af8'}], 'FC': []}, 'packages2': {'kernel': {'release': '2.fc16.x86_64', 'buildtime': 1330952139.0, 'version': '3.2.9'}, 'spice-server': {'release': '1.fc16', 'buildtime': '1327339129', 'version': '0.10.1'}, 'vdsm': {'release': '0.183.git107644d.fc16.shuming1336622293', 'buildtime': '1336622307', 'version': '4.9.6'}, 'qemu-kvm': {'release': '4.fc16', 'buildtime': '1327954752', 'version': '0.15.1'}, 'libvirt': {'release': '1.fc17', 'buildtime': '1335562267', 'version': '0.9.11.3'}, 'qemu-img': {'release': '4.fc16', 'buildtime': '1327954752', 'version': '0.15.1'}}, 'cpuModel': 'Intel(R) Xeon(R) CPU           X5650  @ 2.67GHz', 'hooks': {}, 'vmTypes': ['kvm'], 'supportedProtocols': ['2.2', '2.3'], 'networks': {}, 'uuid': '36D82702-FBFD-11E0-9A46-E41F13BE8FA8_00:00:C9:E5:A0:6E', 'lastClientIface': 'ovirtmgmt', 'nics': {'p2p1': {'hwaddr': '00:00:C9:E5:A0:6E', 'netmask': '', 'speed': 0, 'addr': '', 'mtu': '1500'}, 'p2p2': {'hwaddr': '00:00:C9:E5:A0:72', 'netmask': '', 'speed': 0, 'addr': '', 'mtu': '1500'}, 'eth1': {'hwaddr': 'E4:1F:13:BE:8F:AA', 'netmask': '', 'speed': 0, 'addr': '', 'mtu': '1500'}, 'eth0': {'hwaddr': 'E4:1F:13:BE:8F:A8', 'netmask': '', 'speed': 100, 'addr': '', 'mtu': '1500'}}, 'software_revision': '0', 'management_ip': '', 'clusterLevels': ['3.0', '3.1'], 'cpuFlags': u'fpu,vme,de,pse,tsc,msr,pae,mce,cx8,apic,sep,mtrr,pge,mca,cmov,pat,pse36,clflush,dts,acpi,mmx,fxsr,sse,sse2,ss,ht,tm,pbe,syscall,nx,pdpe1gb,rdtscp,lm,constant_tsc,arch_perfmon,pebs,bts,rep_good,nopl,xtopology,nonstop_tsc,aperfmperf,pni,pclmulqdq,dtes64,monitor,ds_cpl,vmx,smx,est,tm2,ssse3,cx16,xtpr,pdcm,pcid,dca,sse4_1,sse4_2,popcnt,aes,lahf_lm,arat,epb,dts,tpr_shadow,vnmi,flexpriority,ept,vpid,model_coreduo,model_Conroe', 'ISCSIInitiatorName': 'iqn.1994-05.com.redhat:f1b658ea7af8', 'memSize': '72486', '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.9', 'cpuSpeed': '1596.000', 'cpuSockets': '2', 'vlans': {}, 'cpuCores': '12', 'kvmEnabled': 'true', 'guestOverhead': '65', 'supportedRHEVMs': ['3.0'], 'version_name': 'Snow Man', 'emulatedMachines': [u'pc-0.14', u'pc', u'fedora-13', u'pc-0.13', u'pc-0.12', u'pc-0.11', u'pc-0.10', u'isapc', u'pc-0.14', u'pc', u'fedora-13', u'pc-0.13', u'pc-0.12', u'pc-0.11', u'pc-0.10', u'isapc'], 'operatingSystem': {'release': '1', 'version': '16', 'name': 'oVirt Node'}, 'lastClient': '9.181.129.153'}}
Thread-17::DEBUG::2012-05-16 18:26:21,091::BindingXMLRPC::864::vds::(wrapper) client [9.181.129.153]::call getCapabilities with () {} flowID [26f61ef0]
Thread-17::DEBUG::2012-05-16 18:26:21,115::__init__::1249::Storage.Misc.excCmd::(_log) '/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" qemu-kvm' (cwd None)
Thread-17::DEBUG::2012-05-16 18:26:21,146::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-17::DEBUG::2012-05-16 18:26:21,147::__init__::1249::Storage.Misc.excCmd::(_log) '/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" qemu-img' (cwd None)
Thread-17::DEBUG::2012-05-16 18:26:21,172::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-17::DEBUG::2012-05-16 18:26:21,173::__init__::1249::Storage.Misc.excCmd::(_log) '/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" vdsm' (cwd None)
Thread-17::DEBUG::2012-05-16 18:26:21,194::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-17::DEBUG::2012-05-16 18:26:21,195::__init__::1249::Storage.Misc.excCmd::(_log) '/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" spice-server' (cwd None)
Thread-17::DEBUG::2012-05-16 18:26:21,217::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-17::DEBUG::2012-05-16 18:26:21,218::__init__::1249::Storage.Misc.excCmd::(_log) '/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" libvirt' (cwd None)
Thread-17::DEBUG::2012-05-16 18:26:21,242::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-17::DEBUG::2012-05-16 18:26:21,243::BindingXMLRPC::870::vds::(wrapper) return getCapabilities with {'status': {'message': 'Done', 'code': 0}, 'info': {'HBAInventory': {'iSCSI': [{'InitiatorName': 'iqn.1994-05.com.redhat:f1b658ea7af8'}], 'FC': []}, 'packages2': {'kernel': {'release': '2.fc16.x86_64', 'buildtime': 1330952139.0, 'version': '3.2.9'}, 'spice-server': {'release': '1.fc16', 'buildtime': '1327339129', 'version': '0.10.1'}, 'vdsm': {'release': '0.183.git107644d.fc16.shuming1336622293', 'buildtime': '1336622307', 'version': '4.9.6'}, 'qemu-kvm': {'release': '4.fc16', 'buildtime': '1327954752', 'version': '0.15.1'}, 'libvirt': {'release': '1.fc17', 'buildtime': '1335562267', 'version': '0.9.11.3'}, 'qemu-img': {'release': '4.fc16', 'buildtime': '1327954752', 'version': '0.15.1'}}, 'cpuModel': 'Intel(R) Xeon(R) CPU           X5650  @ 2.67GHz', 'hooks': {}, 'vmTypes': ['kvm'], 'supportedProtocols': ['2.2', '2.3'], 'networks': {}, 'uuid': '36D82702-FBFD-11E0-9A46-E41F13BE8FA8_00:00:C9:E5:A0:6E', 'lastClientIface': 'ovirtmgmt', 'nics': {'p2p1': {'hwaddr': '00:00:C9:E5:A0:6E', 'netmask': '', 'speed': 0, 'addr': '', 'mtu': '1500'}, 'p2p2': {'hwaddr': '00:00:C9:E5:A0:72', 'netmask': '', 'speed': 0, 'addr': '', 'mtu': '1500'}, 'eth1': {'hwaddr': 'E4:1F:13:BE:8F:AA', 'netmask': '', 'speed': 0, 'addr': '', 'mtu': '1500'}, 'eth0': {'hwaddr': 'E4:1F:13:BE:8F:A8', 'netmask': '', 'speed': 100, 'addr': '', 'mtu': '1500'}}, 'software_revision': '0', 'management_ip': '', 'clusterLevels': ['3.0', '3.1'], 'cpuFlags': u'fpu,vme,de,pse,tsc,msr,pae,mce,cx8,apic,sep,mtrr,pge,mca,cmov,pat,pse36,clflush,dts,acpi,mmx,fxsr,sse,sse2,ss,ht,tm,pbe,syscall,nx,pdpe1gb,rdtscp,lm,constant_tsc,arch_perfmon,pebs,bts,rep_good,nopl,xtopology,nonstop_tsc,aperfmperf,pni,pclmulqdq,dtes64,monitor,ds_cpl,vmx,smx,est,tm2,ssse3,cx16,xtpr,pdcm,pcid,dca,sse4_1,sse4_2,popcnt,aes,lahf_lm,arat,epb,dts,tpr_shadow,vnmi,flexpriority,ept,vpid,model_coreduo,model_Conroe', 'ISCSIInitiatorName': 'iqn.1994-05.com.redhat:f1b658ea7af8', 'memSize': '72486', '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.9', 'cpuSpeed': '1596.000', 'cpuSockets': '2', 'vlans': {}, 'cpuCores': '12', 'kvmEnabled': 'true', 'guestOverhead': '65', 'supportedRHEVMs': ['3.0'], 'version_name': 'Snow Man', 'emulatedMachines': [u'pc-0.14', u'pc', u'fedora-13', u'pc-0.13', u'pc-0.12', u'pc-0.11', u'pc-0.10', u'isapc', u'pc-0.14', u'pc', u'fedora-13', u'pc-0.13', u'pc-0.12', u'pc-0.11', u'pc-0.10', u'isapc'], 'operatingSystem': {'release': '1', 'version': '16', 'name': 'oVirt Node'}, 'lastClient': '9.181.129.153'}}