MainThread::INFO::2012-10-25 16:56:40,980::vdsm::70::vds::(run) I am the actual vdsm 4.10-10
MainThread::DEBUG::2012-10-25 16:56:42,126::resourceManager::379::ResourceManager::(registerNamespace) Registering namespace 'Storage'
MainThread::DEBUG::2012-10-25 16:56:42,127::threadPool::45::Misc.ThreadPool::(__init__) Enter - numThreads: 10.0, waitTimeout: 3, maxTasks: 500.0
MainThread::DEBUG::2012-10-25 16:56:42,309::multipath::110::Storage.Multipath::(isEnabled) multipath Defaulting to False
MainThread::DEBUG::2012-10-25 16:56:42,310::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /usr/bin/cp /tmp/tmp55dBBo /etc/multipath.conf' (cwd None)
MainThread::DEBUG::2012-10-25 16:56:42,324::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
MainThread::DEBUG::2012-10-25 16:56:42,324::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/multipath -F' (cwd None)
MainThread::DEBUG::2012-10-25 16:56:42,339::__init__::1249::Storage.Misc.excCmd::(_log) FAILED: <err> = ''; <rc> = 1
MainThread::DEBUG::2012-10-25 16:56:42,340::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /usr/sbin/service multipathd restart' (cwd None)
MainThread::DEBUG::2012-10-25 16:56:42,600::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = 'Redirecting to /bin/systemctl restart  multipathd.service\n'; <rc> = 0
MainThread::DEBUG::2012-10-25 16:56:42,601::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/lvm dumpconfig global/locking_type' (cwd None)
MainThread::DEBUG::2012-10-25 16:56:36,031::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
MainThread::DEBUG::2012-10-25 16:56:36,032::lvm::316::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' got the operation mutex
MainThread::DEBUG::2012-10-25 16:56:36,033::__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 = [ \\"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-10-25 16:56:36,296::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
MainThread::DEBUG::2012-10-25 16:56:36,297::lvm::339::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' released the operation mutex
MainThread::DEBUG::2012-10-25 16:56:36,297::lvm::349::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
MainThread::DEBUG::2012-10-25 16:56:36,297::__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 = [ \\"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-10-25 16:56:36,347::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
MainThread::DEBUG::2012-10-25 16:56:36,348::lvm::376::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
MainThread::DEBUG::2012-10-25 16:56:36,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 = [ \\"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-10-25 16:56:36,399::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
Thread-12::DEBUG::2012-10-25 16:56:36,400::misc::1053::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
MainThread::INFO::2012-10-25 16:56:36,401::dispatcher::95::Storage.Dispatcher::(__init__) Starting StorageDispatcher...
Thread-12::DEBUG::2012-10-25 16:56:36,402::misc::1055::SamplingMethod::(__call__) Got in to sampling method
Thread-12::DEBUG::2012-10-25 16:56:36,402::misc::1053::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
Thread-12::DEBUG::2012-10-25 16:56:36,403::misc::1055::SamplingMethod::(__call__) Got in to sampling method
Thread-12::DEBUG::2012-10-25 16:56:36,403::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
MainThread::DEBUG::2012-10-25 16:56:36,417::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/pgrep -xf ksmd' (cwd None)
Thread-12::DEBUG::2012-10-25 16:56:36,421::__init__::1249::Storage.Misc.excCmd::(_log) FAILED: <err> = 'iscsiadm: No session found.\n'; <rc> = 21
Thread-12::DEBUG::2012-10-25 16:56:36,422::misc::1063::SamplingMethod::(__call__) Returning last result
Thread-12::DEBUG::2012-10-25 16:56:36,422::supervdsm::103::SuperVdsmProxy::(_killSupervdsm) Could not kill old Super Vdsm [Errno 2] No such file or directory: '/var/run/vdsm/svdsm.pid'
Thread-12::DEBUG::2012-10-25 16:56:36,423::supervdsm::91::SuperVdsmProxy::(_launchSupervdsm) Launching Super Vdsm
Thread-12::DEBUG::2012-10-25 16:56:36,423::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /usr/bin/python /usr/share/vdsm/supervdsmServer.py d8a8a8a6-ca0f-493a-ae03-1801febdf431 10510' (cwd None)
MainThread::DEBUG::2012-10-25 16:56:36,450::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
MainThread::INFO::2012-10-25 16:56:36,451::vmChannels::139::vds::(settimeout) Setting channels' timeout to 30 seconds.
VM Channels Listener::INFO::2012-10-25 16:56:36,452::vmChannels::127::vds::(run) Starting VM channels listener thread.
MainThread::ERROR::2012-10-25 16:56:36,536::clientIF::151::vds::(_prepareBindings) Unable to load the rest server module. Please make sure it is installed.
MainThread::DEBUG::2012-10-25 16:56:37,577::supervdsmServer::306::SuperVdsm.Server::(main) Making sure I'm root
MainThread::DEBUG::2012-10-25 16:56:37,578::supervdsmServer::310::SuperVdsm.Server::(main) Parsing cmd args
MainThread::DEBUG::2012-10-25 16:56:37,578::supervdsmServer::313::SuperVdsm.Server::(main) Creating PID file
MainThread::DEBUG::2012-10-25 16:56:37,578::supervdsmServer::317::SuperVdsm.Server::(main) Cleaning old socket
MainThread::DEBUG::2012-10-25 16:56:37,578::supervdsmServer::321::SuperVdsm.Server::(main) Setting up keep alive thread
MainThread::DEBUG::2012-10-25 16:56:37,579::supervdsmServer::327::SuperVdsm.Server::(main) Creating remote object manager
MainThread::DEBUG::2012-10-25 16:56:37,580::supervdsmServer::338::SuperVdsm.Server::(main) Started serving super vdsm object
MainThread::INFO::2012-10-25 16:56:38,979::vdsm::70::vds::(run) I am the actual vdsm 4.10-10
MainThread::DEBUG::2012-10-25 16:56:39,147::resourceManager::379::ResourceManager::(registerNamespace) Registering namespace 'Storage'
MainThread::DEBUG::2012-10-25 16:56:39,148::threadPool::45::Misc.ThreadPool::(__init__) Enter - numThreads: 10.0, waitTimeout: 3, maxTasks: 500.0
MainThread::DEBUG::2012-10-25 16:56:39,196::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /usr/bin/kill -9 10637' (cwd None)
MainThread::DEBUG::2012-10-25 16:56:39,209::__init__::1249::Storage.Misc.excCmd::(_log) FAILED: <err> = 'kill 10637: No such process\n'; <rc> = 1
MainThread::DEBUG::2012-10-25 16:56:39,209::supervdsm::91::SuperVdsmProxy::(_launchSupervdsm) Launching Super Vdsm
MainThread::DEBUG::2012-10-25 16:56:39,210::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /usr/bin/python /usr/share/vdsm/supervdsmServer.py a7006d35-b94c-4a64-9f74-aca6460f43c7 10855' (cwd None)
MainThread::DEBUG::2012-10-25 16:56:39,348::supervdsmServer::306::SuperVdsm.Server::(main) Making sure I'm root
MainThread::DEBUG::2012-10-25 16:56:39,348::supervdsmServer::310::SuperVdsm.Server::(main) Parsing cmd args
MainThread::DEBUG::2012-10-25 16:56:39,348::supervdsmServer::313::SuperVdsm.Server::(main) Creating PID file
MainThread::DEBUG::2012-10-25 16:56:39,348::supervdsmServer::317::SuperVdsm.Server::(main) Cleaning old socket
MainThread::DEBUG::2012-10-25 16:56:39,348::supervdsmServer::321::SuperVdsm.Server::(main) Setting up keep alive thread
MainThread::DEBUG::2012-10-25 16:56:39,349::supervdsmServer::327::SuperVdsm.Server::(main) Creating remote object manager
MainThread::DEBUG::2012-10-25 16:56:39,350::supervdsmServer::338::SuperVdsm.Server::(main) Started serving super vdsm object
MainThread::DEBUG::2012-10-25 16:56:41,215::supervdsm::113::SuperVdsmProxy::(_connect) Trying to connect to Super Vdsm
MainThread::DEBUG::2012-10-25 16:56:41,221::supervdsm::84::SuperVdsmProxy::(__init__) Connected to Super Vdsm
MainThread::DEBUG::2012-10-25 16:56:41,223::multipath::102::Storage.Multipath::(isEnabled) Current revision of multipath.conf detected, preserving
MainThread::DEBUG::2012-10-25 16:56:41,223::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/lvm dumpconfig global/locking_type' (cwd None)
MainThread::DEBUG::2012-10-25 16:56:41,273::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
MainThread::DEBUG::2012-10-25 16:56:41,273::lvm::316::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' got the operation mutex
MainThread::DEBUG::2012-10-25 16:56:41,274::__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 = [ \\"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-10-25 16:56:41,330::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
MainThread::DEBUG::2012-10-25 16:56:41,330::lvm::339::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' released the operation mutex
MainThread::DEBUG::2012-10-25 16:56:41,330::lvm::349::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
MainThread::DEBUG::2012-10-25 16:56:41,331::__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 = [ \\"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-10-25 16:56:41,378::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
MainThread::DEBUG::2012-10-25 16:56:41,378::lvm::376::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
MainThread::DEBUG::2012-10-25 16:56:41,379::__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 = [ \\"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-10-25 16:56:41,429::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
Thread-12::DEBUG::2012-10-25 16:56:41,429::misc::1053::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
MainThread::INFO::2012-10-25 16:56:41,431::dispatcher::95::Storage.Dispatcher::(__init__) Starting StorageDispatcher...
Thread-12::DEBUG::2012-10-25 16:56:41,431::misc::1055::SamplingMethod::(__call__) Got in to sampling method
Thread-12::DEBUG::2012-10-25 16:56:41,432::misc::1053::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
Thread-12::DEBUG::2012-10-25 16:56:41,432::misc::1055::SamplingMethod::(__call__) Got in to sampling method
Thread-12::DEBUG::2012-10-25 16:56:41,433::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
MainThread::DEBUG::2012-10-25 16:56:41,443::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/pgrep -xf ksmd' (cwd None)
Thread-12::DEBUG::2012-10-25 16:56:41,448::__init__::1249::Storage.Misc.excCmd::(_log) FAILED: <err> = 'iscsiadm: No session found.\n'; <rc> = 21
Thread-12::DEBUG::2012-10-25 16:56:41,448::misc::1063::SamplingMethod::(__call__) Returning last result
MainThread::DEBUG::2012-10-25 16:56:41,472::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
MainThread::INFO::2012-10-25 16:56:41,473::vmChannels::139::vds::(settimeout) Setting channels' timeout to 30 seconds.
VM Channels Listener::INFO::2012-10-25 16:56:41,474::vmChannels::127::vds::(run) Starting VM channels listener thread.
MainThread::ERROR::2012-10-25 16:56:41,477::clientIF::151::vds::(_prepareBindings) Unable to load the rest server module. Please make sure it is installed.
Thread-12::DEBUG::2012-10-25 16:56:43,450::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/multipath' (cwd None)
Thread-12::DEBUG::2012-10-25 16:56:43,496::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-12::DEBUG::2012-10-25 16:56:43,497::lvm::457::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-12::DEBUG::2012-10-25 16:56:43,497::lvm::459::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-12::DEBUG::2012-10-25 16:56:43,497::lvm::469::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
Thread-12::DEBUG::2012-10-25 16:56:43,498::lvm::471::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
Thread-12::DEBUG::2012-10-25 16:56:43,498::lvm::490::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-12::DEBUG::2012-10-25 16:56:43,498::lvm::492::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-12::DEBUG::2012-10-25 16:56:43,498::misc::1063::SamplingMethod::(__call__) Returning last result
Thread-12::DEBUG::2012-10-25 16:56:43,499::hsm::362::Storage.HSM::(__cleanStorageRepository) Started cleaning storage repository at '/rhev/data-center'
Thread-12::DEBUG::2012-10-25 16:56:43,505::hsm::394::Storage.HSM::(__cleanStorageRepository) White list: ['/rhev/data-center/hsm-tasks', '/rhev/data-center/hsm-tasks/*', '/rhev/data-center/mnt']
Thread-12::DEBUG::2012-10-25 16:56:43,506::hsm::395::Storage.HSM::(__cleanStorageRepository) Mount list: []
Thread-12::DEBUG::2012-10-25 16:56:43,506::hsm::397::Storage.HSM::(__cleanStorageRepository) Cleaning leftovers
Thread-12::DEBUG::2012-10-25 16:56:43,508::hsm::440::Storage.HSM::(__cleanStorageRepository) Finished cleaning storage repository at '/rhev/data-center'
MainThread::INFO::2012-10-25 16:56:46,483::vmChannels::135::vds::(stop) VM channels listener was stopped.
MainThread::DEBUG::2012-10-25 16:56:46,485::task::588::TaskManager.Task::(_updateState) Task=`90c8c0e8-4a28-4583-abaf-36af8ca1c106`::moving from state init -> state preparing
MainThread::INFO::2012-10-25 16:56:46,485::logUtils::37::dispatcher::(wrapper) Run and protect: prepareForShutdown(options=None)
Thread-11::DEBUG::2012-10-25 16:56:46,485::storageServer::617::ConnectionMonitor::(_monitorConnections) Monitoring stopped
MainThread::DEBUG::2012-10-25 16:56:46,526::taskManager::80::TaskManager::(prepareForShutdown) Request to stop all tasks
MainThread::INFO::2012-10-25 16:56:46,526::logUtils::39::dispatcher::(wrapper) Run and protect: prepareForShutdown, Return response: None
MainThread::DEBUG::2012-10-25 16:56:46,526::task::1172::TaskManager.Task::(prepare) Task=`90c8c0e8-4a28-4583-abaf-36af8ca1c106`::finished: None
MainThread::DEBUG::2012-10-25 16:56:46,526::task::588::TaskManager.Task::(_updateState) Task=`90c8c0e8-4a28-4583-abaf-36af8ca1c106`::moving from state preparing -> state finished
MainThread::DEBUG::2012-10-25 16:56:46,527::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
MainThread::DEBUG::2012-10-25 16:56:46,527::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
MainThread::DEBUG::2012-10-25 16:56:46,527::task::978::TaskManager.Task::(_decref) Task=`90c8c0e8-4a28-4583-abaf-36af8ca1c106`::ref 0 aborting False
MainThread::INFO::2012-10-25 16:56:46,527::vdsm::75::vds::(run) VDSM main thread ended. Waiting for 13 other threads...
MainThread::INFO::2012-10-25 16:56:46,527::vdsm::78::vds::(run) <_MainThread(MainThread, started 139797172700992)>
MainThread::INFO::2012-10-25 16:56:46,527::vdsm::78::vds::(run) <Thread(libvirtEventLoop, started daemon 139796934248192)>
MainThread::INFO::2012-10-25 16:56:46,527::vdsm::78::vds::(run) <WorkerThread(Thread-5, started daemon 139796789835520)>
MainThread::INFO::2012-10-25 16:56:46,527::vmChannels::135::vds::(stop) VM channels listener was stopped.
MainThread::INFO::2012-10-25 16:56:46,528::vdsm::78::vds::(run) <Listener(VM Channels Listener, started daemon 139795741271808)>
MainThread::INFO::2012-10-25 16:56:46,528::vdsm::78::vds::(run) <WorkerThread(Thread-4, started daemon 139796798228224)>
MainThread::INFO::2012-10-25 16:56:46,528::vdsm::78::vds::(run) <KsmMonitorThread(KsmMonitor, started daemon 139796236179200)>
MainThread::INFO::2012-10-25 16:56:46,528::vdsm::78::vds::(run) <WorkerThread(Thread-3, started daemon 139796806620928)>
MainThread::INFO::2012-10-25 16:56:46,528::vdsm::78::vds::(run) <WorkerThread(Thread-9, started daemon 139796278142720)>
MainThread::INFO::2012-10-25 16:56:46,528::vdsm::78::vds::(run) <WorkerThread(Thread-8, started daemon 139796286535424)>
MainThread::INFO::2012-10-25 16:56:46,528::vdsm::78::vds::(run) <WorkerThread(Thread-1, started daemon 139796823406336)>
MainThread::INFO::2012-10-25 16:56:46,528::vdsm::78::vds::(run) <WorkerThread(Thread-6, started daemon 139796781442816)>
MainThread::INFO::2012-10-25 16:56:46,528::vdsm::78::vds::(run) <WorkerThread(Thread-10, started daemon 139796269750016)>
MainThread::INFO::2012-10-25 16:56:46,529::vdsm::78::vds::(run) <WorkerThread(Thread-7, started daemon 139796773050112)>
MainThread::INFO::2012-10-25 16:56:46,529::vdsm::78::vds::(run) <WorkerThread(Thread-2, started daemon 139796815013632)>
MainThread::INFO::2012-10-25 16:56:48,364::vdsm::70::vds::(run) I am the actual vdsm 4.10-10
MainThread::DEBUG::2012-10-25 16:56:48,530::resourceManager::379::ResourceManager::(registerNamespace) Registering namespace 'Storage'
MainThread::DEBUG::2012-10-25 16:56:48,530::threadPool::45::Misc.ThreadPool::(__init__) Enter - numThreads: 10.0, waitTimeout: 3, maxTasks: 500.0
MainThread::DEBUG::2012-10-25 16:56:48,576::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /usr/bin/kill -9 10876' (cwd None)
MainThread::DEBUG::2012-10-25 16:56:48,589::__init__::1249::Storage.Misc.excCmd::(_log) FAILED: <err> = 'kill 10876: No such process\n'; <rc> = 1
MainThread::DEBUG::2012-10-25 16:56:48,590::supervdsm::91::SuperVdsmProxy::(_launchSupervdsm) Launching Super Vdsm
MainThread::DEBUG::2012-10-25 16:56:48,590::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /usr/bin/python /usr/share/vdsm/supervdsmServer.py 79796518-f987-45a2-9797-cff29942a8b8 11202' (cwd None)
MainThread::DEBUG::2012-10-25 16:56:48,737::supervdsmServer::306::SuperVdsm.Server::(main) Making sure I'm root
MainThread::DEBUG::2012-10-25 16:56:48,737::supervdsmServer::310::SuperVdsm.Server::(main) Parsing cmd args
MainThread::DEBUG::2012-10-25 16:56:48,737::supervdsmServer::313::SuperVdsm.Server::(main) Creating PID file
MainThread::DEBUG::2012-10-25 16:56:48,737::supervdsmServer::317::SuperVdsm.Server::(main) Cleaning old socket
MainThread::DEBUG::2012-10-25 16:56:48,738::supervdsmServer::321::SuperVdsm.Server::(main) Setting up keep alive thread
MainThread::DEBUG::2012-10-25 16:56:48,738::supervdsmServer::327::SuperVdsm.Server::(main) Creating remote object manager
MainThread::DEBUG::2012-10-25 16:56:48,739::supervdsmServer::338::SuperVdsm.Server::(main) Started serving super vdsm object
MainThread::DEBUG::2012-10-25 16:56:50,595::supervdsm::113::SuperVdsmProxy::(_connect) Trying to connect to Super Vdsm
MainThread::DEBUG::2012-10-25 16:56:50,603::supervdsm::84::SuperVdsmProxy::(__init__) Connected to Super Vdsm
MainThread::DEBUG::2012-10-25 16:56:50,604::multipath::102::Storage.Multipath::(isEnabled) Current revision of multipath.conf detected, preserving
MainThread::DEBUG::2012-10-25 16:56:50,604::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/lvm dumpconfig global/locking_type' (cwd None)
MainThread::DEBUG::2012-10-25 16:56:50,651::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
MainThread::DEBUG::2012-10-25 16:56:50,652::lvm::316::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' got the operation mutex
MainThread::DEBUG::2012-10-25 16:56:50,653::__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 = [ \\"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-10-25 16:56:50,710::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
MainThread::DEBUG::2012-10-25 16:56:50,711::lvm::339::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' released the operation mutex
MainThread::DEBUG::2012-10-25 16:56:50,711::lvm::349::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
MainThread::DEBUG::2012-10-25 16:56:50,711::__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 = [ \\"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-10-25 16:56:50,760::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
MainThread::DEBUG::2012-10-25 16:56:50,761::lvm::376::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
MainThread::DEBUG::2012-10-25 16:56:50,761::__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 = [ \\"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-10-25 16:56:50,809::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
Thread-12::DEBUG::2012-10-25 16:56:50,810::misc::1053::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
MainThread::INFO::2012-10-25 16:56:50,812::dispatcher::95::Storage.Dispatcher::(__init__) Starting StorageDispatcher...
Thread-12::DEBUG::2012-10-25 16:56:50,813::misc::1055::SamplingMethod::(__call__) Got in to sampling method
Thread-12::DEBUG::2012-10-25 16:56:50,813::misc::1053::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
Thread-12::DEBUG::2012-10-25 16:56:50,814::misc::1055::SamplingMethod::(__call__) Got in to sampling method
Thread-12::DEBUG::2012-10-25 16:56:50,814::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
MainThread::DEBUG::2012-10-25 16:56:50,828::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/pgrep -xf ksmd' (cwd None)
Thread-12::DEBUG::2012-10-25 16:56:50,833::__init__::1249::Storage.Misc.excCmd::(_log) FAILED: <err> = 'iscsiadm: No session found.\n'; <rc> = 21
Thread-12::DEBUG::2012-10-25 16:56:50,834::misc::1063::SamplingMethod::(__call__) Returning last result
MainThread::DEBUG::2012-10-25 16:56:50,845::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
MainThread::INFO::2012-10-25 16:56:50,847::vmChannels::139::vds::(settimeout) Setting channels' timeout to 30 seconds.
VM Channels Listener::INFO::2012-10-25 16:56:50,848::vmChannels::127::vds::(run) Starting VM channels listener thread.
MainThread::ERROR::2012-10-25 16:56:50,851::clientIF::151::vds::(_prepareBindings) Unable to load the rest server module. Please make sure it is installed.
Thread-14::DEBUG::2012-10-25 16:56:51,131::BindingXMLRPC::859::vds::(wrapper) client [127.0.0.1]::call getCapabilities with () {}
Thread-14::DEBUG::2012-10-25 16:56:51,265::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" qemu-kvm' (cwd None)
Thread-14::DEBUG::2012-10-25 16:56:51,523::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-14::DEBUG::2012-10-25 16:56:51,524::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" qemu-img' (cwd None)
Thread-14::DEBUG::2012-10-25 16:56:51,710::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-14::DEBUG::2012-10-25 16:56:51,710::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" vdsm' (cwd None)
Thread-14::DEBUG::2012-10-25 16:56:51,816::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-14::DEBUG::2012-10-25 16:56:51,816::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" spice-server' (cwd None)
Thread-14::DEBUG::2012-10-25 16:56:51,834::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-14::DEBUG::2012-10-25 16:56:51,834::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" libvirt' (cwd None)
Thread-14::DEBUG::2012-10-25 16:56:51,948::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-14::DEBUG::2012-10-25 16:56:52,116::BindingXMLRPC::865::vds::(wrapper) return getCapabilities with {'status': {'message': 'Done', 'code': 0}, 'info': {'HBAInventory': {'iSCSI': [{'InitiatorName': 'iqn.1994-05.com.redhat:4e8d1c801e'}], 'FC': []}, 'packages2': {'kernel': {'release': '4.fc17.x86_64', 'buildtime': 1350434601.0, 'version': '3.6.2'}, 'spice-server': {'release': '5.fc17', 'buildtime': '1336983054', 'version': '0.10.1'}, 'vdsm': {'release': '10.fc17', 'buildtime': '1349383616', 'version': '4.10.0'}, 'qemu-kvm': {'release': '2.fc17', 'buildtime': '1349642820', 'version': '1.0.1'}, 'libvirt': {'release': '1.fc17', 'buildtime': '1349654831', 'version': '0.9.11.6'}, 'qemu-img': {'release': '2.fc17', 'buildtime': '1349642820', 'version': '1.0.1'}}, 'cpuModel': 'Intel(R) Xeon(R) CPU           X5650  @ 2.67GHz', 'hooks': {}, 'vmTypes': ['kvm'], 'supportedProtocols': ['2.2', '2.3'], 'networks': {}, 'uuid': '7DBB734F-D7B9-11DF-BBDA-DE3301D81CC1_00:1b:21:cf:2e:a8', 'lastClientIface': '', 'nics': {'eth3': {'hwaddr': '00:1b:21:cf:2e:a9', 'netmask': '', 'speed': 0, 'addr': '', 'mtu': '1500'}, 'eth2': {'hwaddr': '00:1b:21:cf:2e:a8', 'netmask': '', 'speed': 0, 'addr': '', 'mtu': '1500'}, 'eth1': {'hwaddr': '1c:c1:de:33:01:d8', 'netmask': '255.255.255.0', 'speed': 100, 'addr': '10.0.0.1', 'mtu': '1500'}, 'eth0': {'hwaddr': '1c:c1:de:33:01:d9', 'netmask': '', 'speed': 0, 'addr': '', 'mtu': '1500'}}, 'software_revision': '10', '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,ida,arat,epb,dtherm,tpr_shadow,vnmi,flexpriority,ept,vpid,model_coreduo,model_Conroe', 'ISCSIInitiatorName': 'iqn.1994-05.com.redhat:4e8d1c801e', 'netConfigDirty': 'False', 'memSize': '11999', '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': '1596.000', 'cpuSockets': '2', 'vlans': {}, 'cpuCores': '12', 'kvmEnabled': 'true', 'guestOverhead': '65', 'supportedRHEVMs': ['3.0', '3.1'], 'version_name': 'Snow Man', 'emulatedMachines': [u'pc-0.15', u'pc-1.0', u'pc', u'pc-0.14', u'pc-0.13', u'pc-0.12', u'pc-0.11', u'pc-0.10', u'isapc', u'pc-0.15', u'pc-1.0', u'pc', u'pc-0.14', u'pc-0.13', u'pc-0.12', u'pc-0.11', u'pc-0.10', u'isapc'], 'operatingSystem': {'release': '1', 'version': '17', 'name': 'Fedora'}, 'lastClient': '0.0.0.0'}}
Thread-15::DEBUG::2012-10-25 16:56:52,257::BindingXMLRPC::859::vds::(wrapper) client [127.0.0.1]::call getCapabilities with () {} flowID [1c999d8c]
Thread-15::DEBUG::2012-10-25 16:56:52,275::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" qemu-kvm' (cwd None)
Thread-15::DEBUG::2012-10-25 16:56:52,291::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-15::DEBUG::2012-10-25 16:56:52,292::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" qemu-img' (cwd None)
Thread-15::DEBUG::2012-10-25 16:56:52,307::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-15::DEBUG::2012-10-25 16:56:52,307::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" vdsm' (cwd None)
Thread-15::DEBUG::2012-10-25 16:56:52,324::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-15::DEBUG::2012-10-25 16:56:52,325::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" spice-server' (cwd None)
Thread-15::DEBUG::2012-10-25 16:56:52,341::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-15::DEBUG::2012-10-25 16:56:52,341::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" libvirt' (cwd None)
Thread-15::DEBUG::2012-10-25 16:56:52,356::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-15::DEBUG::2012-10-25 16:56:52,357::BindingXMLRPC::865::vds::(wrapper) return getCapabilities with {'status': {'message': 'Done', 'code': 0}, 'info': {'HBAInventory': {'iSCSI': [{'InitiatorName': 'iqn.1994-05.com.redhat:4e8d1c801e'}], 'FC': []}, 'packages2': {'kernel': {'release': '4.fc17.x86_64', 'buildtime': 1350434601.0, 'version': '3.6.2'}, 'spice-server': {'release': '5.fc17', 'buildtime': '1336983054', 'version': '0.10.1'}, 'vdsm': {'release': '10.fc17', 'buildtime': '1349383616', 'version': '4.10.0'}, 'qemu-kvm': {'release': '2.fc17', 'buildtime': '1349642820', 'version': '1.0.1'}, 'libvirt': {'release': '1.fc17', 'buildtime': '1349654831', 'version': '0.9.11.6'}, 'qemu-img': {'release': '2.fc17', 'buildtime': '1349642820', 'version': '1.0.1'}}, 'cpuModel': 'Intel(R) Xeon(R) CPU           X5650  @ 2.67GHz', 'hooks': {}, 'vmTypes': ['kvm'], 'supportedProtocols': ['2.2', '2.3'], 'networks': {}, 'uuid': '7DBB734F-D7B9-11DF-BBDA-DE3301D81CC1_00:1b:21:cf:2e:a8', 'lastClientIface': '', 'nics': {'eth3': {'hwaddr': '00:1b:21:cf:2e:a9', 'netmask': '', 'speed': 0, 'addr': '', 'mtu': '1500'}, 'eth2': {'hwaddr': '00:1b:21:cf:2e:a8', 'netmask': '', 'speed': 0, 'addr': '', 'mtu': '1500'}, 'eth1': {'hwaddr': '1c:c1:de:33:01:d8', 'netmask': '255.255.255.0', 'speed': 100, 'addr': '10.0.0.1', 'mtu': '1500'}, 'eth0': {'hwaddr': '1c:c1:de:33:01:d9', 'netmask': '', 'speed': 0, 'addr': '', 'mtu': '1500'}}, 'software_revision': '10', '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,ida,arat,epb,dtherm,tpr_shadow,vnmi,flexpriority,ept,vpid,model_coreduo,model_Conroe', 'ISCSIInitiatorName': 'iqn.1994-05.com.redhat:4e8d1c801e', 'netConfigDirty': 'False', 'memSize': '11999', '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': '1596.000', 'cpuSockets': '2', 'vlans': {}, 'cpuCores': '12', 'kvmEnabled': 'true', 'guestOverhead': '65', 'supportedRHEVMs': ['3.0', '3.1'], 'version_name': 'Snow Man', 'emulatedMachines': [u'pc-0.15', u'pc-1.0', u'pc', u'pc-0.14', u'pc-0.13', u'pc-0.12', u'pc-0.11', u'pc-0.10', u'isapc', u'pc-0.15', u'pc-1.0', u'pc', u'pc-0.14', u'pc-0.13', u'pc-0.12', u'pc-0.11', u'pc-0.10', u'isapc'], 'operatingSystem': {'release': '1', 'version': '17', 'name': 'Fedora'}, 'lastClient': '127.0.0.1'}}
Thread-12::DEBUG::2012-10-25 16:56:52,834::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/multipath' (cwd None)
Thread-12::DEBUG::2012-10-25 16:56:52,877::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-12::DEBUG::2012-10-25 16:56:52,877::lvm::457::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-12::DEBUG::2012-10-25 16:56:52,878::lvm::459::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-12::DEBUG::2012-10-25 16:56:52,878::lvm::469::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
Thread-12::DEBUG::2012-10-25 16:56:52,878::lvm::471::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
Thread-12::DEBUG::2012-10-25 16:56:52,879::lvm::490::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-12::DEBUG::2012-10-25 16:56:52,879::lvm::492::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-12::DEBUG::2012-10-25 16:56:52,879::misc::1063::SamplingMethod::(__call__) Returning last result
Thread-12::DEBUG::2012-10-25 16:56:52,879::hsm::362::Storage.HSM::(__cleanStorageRepository) Started cleaning storage repository at '/rhev/data-center'
Thread-12::DEBUG::2012-10-25 16:56:52,885::hsm::394::Storage.HSM::(__cleanStorageRepository) White list: ['/rhev/data-center/hsm-tasks', '/rhev/data-center/hsm-tasks/*', '/rhev/data-center/mnt']
Thread-12::DEBUG::2012-10-25 16:56:52,886::hsm::395::Storage.HSM::(__cleanStorageRepository) Mount list: []
Thread-12::DEBUG::2012-10-25 16:56:52,886::hsm::397::Storage.HSM::(__cleanStorageRepository) Cleaning leftovers
Thread-12::DEBUG::2012-10-25 16:56:52,887::hsm::440::Storage.HSM::(__cleanStorageRepository) Finished cleaning storage repository at '/rhev/data-center'
Thread-17::DEBUG::2012-10-25 17:00:00,072::BindingXMLRPC::859::vds::(wrapper) client [127.0.0.1]::call getCapabilities with () {} flowID [5ea886d]
Thread-17::DEBUG::2012-10-25 17:00:00,091::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" qemu-kvm' (cwd None)
Thread-17::DEBUG::2012-10-25 17:00:00,112::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-17::DEBUG::2012-10-25 17:00:00,113::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" qemu-img' (cwd None)
Thread-17::DEBUG::2012-10-25 17:00:00,132::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-17::DEBUG::2012-10-25 17:00:00,132::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" vdsm' (cwd None)
Thread-17::DEBUG::2012-10-25 17:00:00,147::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-17::DEBUG::2012-10-25 17:00:00,148::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" spice-server' (cwd None)
Thread-17::DEBUG::2012-10-25 17:00:00,165::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-17::DEBUG::2012-10-25 17:00:00,165::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" libvirt' (cwd None)
Thread-17::DEBUG::2012-10-25 17:00:00,181::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-17::DEBUG::2012-10-25 17:00:00,182::BindingXMLRPC::865::vds::(wrapper) return getCapabilities with {'status': {'message': 'Done', 'code': 0}, 'info': {'HBAInventory': {'iSCSI': [{'InitiatorName': 'iqn.1994-05.com.redhat:4e8d1c801e'}], 'FC': []}, 'packages2': {'kernel': {'release': '4.fc17.x86_64', 'buildtime': 1350434601.0, 'version': '3.6.2'}, 'spice-server': {'release': '5.fc17', 'buildtime': '1336983054', 'version': '0.10.1'}, 'vdsm': {'release': '10.fc17', 'buildtime': '1349383616', 'version': '4.10.0'}, 'qemu-kvm': {'release': '2.fc17', 'buildtime': '1349642820', 'version': '1.0.1'}, 'libvirt': {'release': '1.fc17', 'buildtime': '1349654831', 'version': '0.9.11.6'}, 'qemu-img': {'release': '2.fc17', 'buildtime': '1349642820', 'version': '1.0.1'}}, 'cpuModel': 'Intel(R) Xeon(R) CPU           X5650  @ 2.67GHz', 'hooks': {}, 'vmTypes': ['kvm'], 'supportedProtocols': ['2.2', '2.3'], 'networks': {}, 'uuid': '7DBB734F-D7B9-11DF-BBDA-DE3301D81CC1_00:1b:21:cf:2e:a8', 'lastClientIface': '', 'nics': {'eth3': {'hwaddr': '00:1b:21:cf:2e:a9', 'netmask': '', 'speed': 0, 'addr': '', 'mtu': '1500'}, 'eth2': {'hwaddr': '00:1b:21:cf:2e:a8', 'netmask': '', 'speed': 0, 'addr': '', 'mtu': '1500'}, 'eth1': {'hwaddr': '1c:c1:de:33:01:d8', 'netmask': '255.255.255.0', 'speed': 100, 'addr': '10.0.0.1', 'mtu': '1500'}, 'eth0': {'hwaddr': '1c:c1:de:33:01:d9', 'netmask': '', 'speed': 0, 'addr': '', 'mtu': '1500'}}, 'software_revision': '10', '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,ida,arat,epb,dtherm,tpr_shadow,vnmi,flexpriority,ept,vpid,model_coreduo,model_Conroe', 'ISCSIInitiatorName': 'iqn.1994-05.com.redhat:4e8d1c801e', 'netConfigDirty': 'False', 'memSize': '11999', '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': '1596.000', 'cpuSockets': '2', 'vlans': {}, 'cpuCores': '12', 'kvmEnabled': 'true', 'guestOverhead': '65', 'supportedRHEVMs': ['3.0', '3.1'], 'version_name': 'Snow Man', 'emulatedMachines': [u'pc-0.15', u'pc-1.0', u'pc', u'pc-0.14', u'pc-0.13', u'pc-0.12', u'pc-0.11', u'pc-0.10', u'isapc', u'pc-0.15', u'pc-1.0', u'pc', u'pc-0.14', u'pc-0.13', u'pc-0.12', u'pc-0.11', u'pc-0.10', u'isapc'], 'operatingSystem': {'release': '1', 'version': '17', 'name': 'Fedora'}, 'lastClient': '127.0.0.1'}}
Thread-18::DEBUG::2012-10-25 17:05:00,074::BindingXMLRPC::859::vds::(wrapper) client [127.0.0.1]::call getCapabilities with () {} flowID [542ad756]
Thread-18::DEBUG::2012-10-25 17:05:00,092::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" qemu-kvm' (cwd None)
Thread-18::DEBUG::2012-10-25 17:05:00,112::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-18::DEBUG::2012-10-25 17:05:00,112::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" qemu-img' (cwd None)
Thread-18::DEBUG::2012-10-25 17:05:00,129::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-18::DEBUG::2012-10-25 17:05:00,129::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" vdsm' (cwd None)
Thread-18::DEBUG::2012-10-25 17:05:00,147::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-18::DEBUG::2012-10-25 17:05:00,147::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" spice-server' (cwd None)
Thread-18::DEBUG::2012-10-25 17:05:00,165::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-18::DEBUG::2012-10-25 17:05:00,166::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" libvirt' (cwd None)
Thread-18::DEBUG::2012-10-25 17:05:00,182::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-18::DEBUG::2012-10-25 17:05:00,183::BindingXMLRPC::865::vds::(wrapper) return getCapabilities with {'status': {'message': 'Done', 'code': 0}, 'info': {'HBAInventory': {'iSCSI': [{'InitiatorName': 'iqn.1994-05.com.redhat:4e8d1c801e'}], 'FC': []}, 'packages2': {'kernel': {'release': '4.fc17.x86_64', 'buildtime': 1350434601.0, 'version': '3.6.2'}, 'spice-server': {'release': '5.fc17', 'buildtime': '1336983054', 'version': '0.10.1'}, 'vdsm': {'release': '10.fc17', 'buildtime': '1349383616', 'version': '4.10.0'}, 'qemu-kvm': {'release': '2.fc17', 'buildtime': '1349642820', 'version': '1.0.1'}, 'libvirt': {'release': '1.fc17', 'buildtime': '1349654831', 'version': '0.9.11.6'}, 'qemu-img': {'release': '2.fc17', 'buildtime': '1349642820', 'version': '1.0.1'}}, 'cpuModel': 'Intel(R) Xeon(R) CPU           X5650  @ 2.67GHz', 'hooks': {}, 'vmTypes': ['kvm'], 'supportedProtocols': ['2.2', '2.3'], 'networks': {}, 'uuid': '7DBB734F-D7B9-11DF-BBDA-DE3301D81CC1_00:1b:21:cf:2e:a8', 'lastClientIface': '', 'nics': {'eth3': {'hwaddr': '00:1b:21:cf:2e:a9', 'netmask': '', 'speed': 0, 'addr': '', 'mtu': '1500'}, 'eth2': {'hwaddr': '00:1b:21:cf:2e:a8', 'netmask': '', 'speed': 0, 'addr': '', 'mtu': '1500'}, 'eth1': {'hwaddr': '1c:c1:de:33:01:d8', 'netmask': '255.255.255.0', 'speed': 100, 'addr': '10.0.0.1', 'mtu': '1500'}, 'eth0': {'hwaddr': '1c:c1:de:33:01:d9', 'netmask': '', 'speed': 0, 'addr': '', 'mtu': '1500'}}, 'software_revision': '10', '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,ida,arat,epb,dtherm,tpr_shadow,vnmi,flexpriority,ept,vpid,model_coreduo,model_Conroe', 'ISCSIInitiatorName': 'iqn.1994-05.com.redhat:4e8d1c801e', 'netConfigDirty': 'False', 'memSize': '11999', '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': '1596.000', 'cpuSockets': '2', 'vlans': {}, 'cpuCores': '12', 'kvmEnabled': 'true', 'guestOverhead': '65', 'supportedRHEVMs': ['3.0', '3.1'], 'version_name': 'Snow Man', 'emulatedMachines': [u'pc-0.15', u'pc-1.0', u'pc', u'pc-0.14', u'pc-0.13', u'pc-0.12', u'pc-0.11', u'pc-0.10', u'isapc', u'pc-0.15', u'pc-1.0', u'pc', u'pc-0.14', u'pc-0.13', u'pc-0.12', u'pc-0.11', u'pc-0.10', u'isapc'], 'operatingSystem': {'release': '1', 'version': '17', 'name': 'Fedora'}, 'lastClient': '127.0.0.1'}}