MainThread::INFO::2013-03-20 21:39:55,765::vdsm::88::vds::(run) I am the actual vdsm 4.10-7 bufferoverflow.home (3.6.10-4.fc18.x86_64)
MainThread::DEBUG::2013-03-20 21:39:55,891::resourceManager::395::ResourceManager::(registerNamespace) Registering namespace 'Storage'
MainThread::DEBUG::2013-03-20 21:39:55,891::threadPool::34::Misc.ThreadPool::(__init__) Enter - numThreads: 10.0, waitTimeout: 3, maxTasks: 500.0
MainThread::WARNING::2013-03-20 21:39:55,896::fileUtils::185::fileUtils::(createdir) Dir /rhev/data-center/mnt already exists
MainThread::DEBUG::2013-03-20 21:39:55,916::supervdsm::122::SuperVdsmProxy::(_start) Launching Super Vdsm
MainThread::DEBUG::2013-03-20 21:39:55,916::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/sudo -n /usr/bin/python /usr/share/vdsm/supervdsmServer.py 77a5c085-c050-498a-a26f-980f1f048e5c 1884 /var/run/vdsm/svdsm.pid /var/run/vdsm/svdsm.time /var/run/vdsm/svdsm.sock 36' (cwd None)
MainThread::DEBUG::2013-03-20 21:39:56,027::supervdsmServer::373::SuperVdsm.Server::(main) Making sure I'm root
MainThread::DEBUG::2013-03-20 21:39:56,027::supervdsmServer::377::SuperVdsm.Server::(main) Parsing cmd args
MainThread::DEBUG::2013-03-20 21:39:56,027::supervdsmServer::381::SuperVdsm.Server::(main) Creating PID and TIMESTAMP files: /var/run/vdsm/svdsm.pid, /var/run/vdsm/svdsm.time
MainThread::DEBUG::2013-03-20 21:39:56,027::supervdsmServer::388::SuperVdsm.Server::(main) Cleaning old socket /var/run/vdsm/svdsm.sock
MainThread::DEBUG::2013-03-20 21:39:56,027::supervdsmServer::392::SuperVdsm.Server::(main) Setting up keep alive thread
MainThread::DEBUG::2013-03-20 21:39:56,027::supervdsmServer::400::SuperVdsm.Server::(main) Creating remote object manager
MainThread::DEBUG::2013-03-20 21:39:56,028::supervdsmServer::412::SuperVdsm.Server::(main) Started serving super vdsm object
MainThread::DEBUG::2013-03-20 21:39:57,921::supervdsm::186::SuperVdsmProxy::(_connect) Trying to connect to Super Vdsm
MainThread::DEBUG::2013-03-20 21:39:57,928::multipath::141::Storage.Multipath::(isEnabled) Current revision of multipath.conf detected, preserving
MainThread::DEBUG::2013-03-20 21:39:57,928::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/sudo -n /sbin/lvm dumpconfig global/locking_type' (cwd None)
MainThread::DEBUG::2013-03-20 21:39:57,943::misc::84::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> = ''; <rc> = 0
MainThread::DEBUG::2013-03-20 21:39:57,944::hsm::434::Storage.HSM::(__cleanStorageRepository) Started cleaning storage repository at '/rhev/data-center'
MainThread::DEBUG::2013-03-20 21:39:57,949::hsm::466::Storage.HSM::(__cleanStorageRepository) White list: ['/rhev/data-center/hsm-tasks', '/rhev/data-center/hsm-tasks/*', '/rhev/data-center/mnt']
MainThread::DEBUG::2013-03-20 21:39:57,949::hsm::467::Storage.HSM::(__cleanStorageRepository) Mount list: []
MainThread::DEBUG::2013-03-20 21:39:57,950::hsm::469::Storage.HSM::(__cleanStorageRepository) Cleaning leftovers
MainThread::DEBUG::2013-03-20 21:39:57,952::hsm::512::Storage.HSM::(__cleanStorageRepository) Finished cleaning storage repository at '/rhev/data-center'
MainThread::INFO::2013-03-20 21:39:57,954::dispatcher::97::Storage.Dispatcher::(__init__) Starting StorageDispatcher...
storageRefresh::DEBUG::2013-03-20 21:39:57,954::lvm::334::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' got the operation mutex
storageRefresh::DEBUG::2013-03-20 21:39:57,956::misc::84::Storage.Misc.excCmd::(<lambda>) '/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)
storageRefresh::DEBUG::2013-03-20 21:39:57,971::misc::84::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> = ''; <rc> = 0
storageRefresh::DEBUG::2013-03-20 21:39:57,971::lvm::359::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' released the operation mutex
storageRefresh::DEBUG::2013-03-20 21:39:57,972::lvm::368::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
storageRefresh::DEBUG::2013-03-20 21:39:57,972::misc::84::Storage.Misc.excCmd::(<lambda>) '/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)
storageRefresh::DEBUG::2013-03-20 21:39:57,982::misc::84::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
storageRefresh::DEBUG::2013-03-20 21:39:57,983::lvm::397::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
storageRefresh::DEBUG::2013-03-20 21:39:57,983::misc::84::Storage.Misc.excCmd::(<lambda>) '/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)
storageRefresh::DEBUG::2013-03-20 21:39:57,995::misc::84::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
storageRefresh::DEBUG::2013-03-20 21:39:57,995::misc::1054::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
storageRefresh::DEBUG::2013-03-20 21:39:57,995::misc::1056::SamplingMethod::(__call__) Got in to sampling method
storageRefresh::DEBUG::2013-03-20 21:39:57,995::misc::1054::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
storageRefresh::DEBUG::2013-03-20 21:39:57,995::misc::1056::SamplingMethod::(__call__) Got in to sampling method
storageRefresh::DEBUG::2013-03-20 21:39:57,996::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
storageRefresh::DEBUG::2013-03-20 21:39:58,003::misc::84::Storage.Misc.excCmd::(<lambda>) FAILED: <err> = 'iscsiadm: No session found.\n'; <rc> = 21
storageRefresh::DEBUG::2013-03-20 21:39:58,003::misc::1064::SamplingMethod::(__call__) Returning last result
MainProcess|storageRefresh::DEBUG::2013-03-20 21:39:58,004::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/dd of=/sys/class/scsi_host/host0/scan' (cwd None)
MainProcess|storageRefresh::DEBUG::2013-03-20 21:39:58,006::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/dd of=/sys/class/scsi_host/host1/scan' (cwd None)
MainThread::INFO::2013-03-20 21:39:58,506::momIF::36::MOM::(__init__) Starting up MOM
MainThread::INFO::2013-03-20 21:39:58,507::vmChannels::140::vds::(settimeout) Setting channels' timeout to 30 seconds.
VM Channels Listener::INFO::2013-03-20 21:39:58,508::vmChannels::128::vds::(run) Starting VM channels listener thread.
MainThread::WARNING::2013-03-20 21:39:58,515::clientIF::175::vds::(_prepareBindings) Unable to load the json rpc server module. Please make sure it is installed.
MainProcess|storageRefresh::DEBUG::2013-03-20 21:39:59,010::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/dd of=/sys/class/scsi_host/host2/scan' (cwd None)
MainProcess|storageRefresh::DEBUG::2013-03-20 21:39:59,013::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/dd of=/sys/class/scsi_host/host3/scan' (cwd None)
MainProcess|storageRefresh::DEBUG::2013-03-20 21:39:59,016::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/dd of=/sys/class/scsi_host/host4/scan' (cwd None)
MainProcess|storageRefresh::DEBUG::2013-03-20 21:39:59,019::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/dd of=/sys/class/scsi_host/host5/scan' (cwd None)
MainProcess|storageRefresh::DEBUG::2013-03-20 21:39:59,022::iscsi::402::Storage.ISCSI::(forceIScsiScan) Performing SCSI scan, this will take up to 30 seconds
storageRefresh::DEBUG::2013-03-20 21:40:01,026::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/sudo -n /sbin/multipath' (cwd None)
storageRefresh::DEBUG::2013-03-20 21:40:01,055::misc::84::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> = ''; <rc> = 0
storageRefresh::DEBUG::2013-03-20 21:40:01,056::lvm::477::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
storageRefresh::DEBUG::2013-03-20 21:40:01,056::lvm::479::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
storageRefresh::DEBUG::2013-03-20 21:40:01,057::lvm::488::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
storageRefresh::DEBUG::2013-03-20 21:40:01,057::lvm::490::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
storageRefresh::DEBUG::2013-03-20 21:40:01,057::lvm::508::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
storageRefresh::DEBUG::2013-03-20 21:40:01,058::lvm::510::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
storageRefresh::DEBUG::2013-03-20 21:40:01,058::misc::1064::SamplingMethod::(__call__) Returning last result
storageRefresh::WARNING::2013-03-20 21:40:01,058::fileUtils::185::fileUtils::(createdir) Dir /rhev/data-center/hsm-tasks already exists
Thread-13::DEBUG::2013-03-20 21:41:49,278::BindingXMLRPC::913::vds::(wrapper) client [10.100.101.108]::call getCapabilities with () {}
Thread-13::DEBUG::2013-03-20 21:41:49,356::BindingXMLRPC::920::vds::(wrapper) return getCapabilities with {'status': {'message': 'Done', 'code': 0}, 'info': {'HBAInventory': {'iSCSI': [{'InitiatorName': 'iqn.1994-05.com.redhat:1031ba876b77'}], 'FC': []}, 'packages2': {'kernel': {'release': '4.fc18.x86_64', 'buildtime': 1355241687.0, 'version': '3.6.10'}, 'spice-server': {'release': '1.fc18', 'buildtime': 1348825855L, 'version': '0.12.0'}, 'vdsm': {'release': '7.fc18', 'buildtime': 1360864703L, 'version': '4.10.3'}, 'qemu-kvm': {'release': '6.fc18', 'buildtime': 1359843954L, 'version': '1.2.2'}, 'libvirt': {'release': '1.fc18', 'buildtime': 1359405439L, 'version': '0.10.2.3'}, 'qemu-img': {'release': '6.fc18', 'buildtime': 1359843954L, 'version': '1.2.2'}, 'mom': {'release': '1.fc18', 'buildtime': 1349470214L, 'version': '0.3.0'}}, 'cpuModel': 'Intel(R) Core(TM) i5-3470 CPU @ 3.20GHz', 'hooks': {}, 'cpuSockets': '1', 'vmTypes': ['kvm'], 'supportedProtocols': ['2.2', '2.3'], 'networks': {'ovirtmgmt': {'iface': 'ovirtmgmt', 'addr': '10.100.101.108', 'cfg': {'DEVICE': 'ovirtmgmt', 'DELAY': '0', 'BOOTPROTO': 'dhcp', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '255.255.255.0', 'stp': 'off', 'bridged': True, 'gateway': '10.100.101.1', 'ports': ['p1p1']}}, 'bridges': {'ovirtmgmt': {'addr': '10.100.101.108', 'cfg': {'DEVICE': 'ovirtmgmt', 'DELAY': '0', 'BOOTPROTO': 'dhcp', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '255.255.255.0', 'stp': 'off', 'ports': ['p1p1']}}, 'uuid': '00000000-0000-0000-0000-D43D7E4F1D65_d4:3d:7e:4f:1d:65', 'lastClientIface': 'ovirtmgmt', 'nics': {'p1p1': {'addr': '', 'cfg': {'DEVICE': 'p1p1', 'BRIDGE': 'ovirtmgmt', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '', 'hwaddr': 'd4:3d:7e:4f:1d:65', 'speed': 100}}, 'software_revision': '7', 'clusterLevels': ['3.0', '3.1', '3.2'], '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,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,sse4_1,sse4_2,x2apic,popcnt,tsc_deadline_timer,aes,xsave,avx,f16c,rdrand,lahf_lm,ida,arat,epb,xsaveopt,pln,pts,dtherm,tpr_shadow,vnmi,flexpriority,ept,vpid,fsgsbase,smep,erms,model_Nehalem,model_Conroe,model_coreduo,model_core2duo,model_Penryn,model_Westmere,model_n270,model_SandyBridge', 'ISCSIInitiatorName': 'iqn.1994-05.com.redhat:1031ba876b77', 'netConfigDirty': 'False', 'supportedENGINEs': ['3.0', '3.1'], 'reservedMem': '321', 'bondings': {}, 'software_version': '4.10', 'memSize': '15916', 'cpuSpeed': '3201.000', 'version_name': 'Snow Man', 'vlans': {}, 'cpuCores': '4', 'kvmEnabled': 'true', 'guestOverhead': '65', 'management_ip': '', 'cpuThreads': '4', 'emulatedMachines': [u'pc-1.2', u'none', u'pc', u'pc-1.1', u'pc-1.0', u'pc-0.15', u'pc-0.14', u'pc-0.13', u'pc-0.12', u'pc-0.11', u'pc-0.10', u'isapc', u'pc-1.2', u'none', u'pc', u'pc-1.1', u'pc-1.0', u'pc-0.15', 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': '18', 'name': 'Fedora'}, 'lastClient': '0.0.0.0'}}
Thread-14::DEBUG::2013-03-20 21:41:49,405::BindingXMLRPC::913::vds::(wrapper) client [10.100.101.108]::call getHardwareInfo with () {}
Thread-14::DEBUG::2013-03-20 21:41:49,435::BindingXMLRPC::920::vds::(wrapper) return getHardwareInfo with {'status': {'message': 'Done', 'code': 0}, 'info': {'systemProductName': 'MS-7808', 'systemSerialNumber': 'To be filled by O.E.M.', 'systemFamily': 'To be filled by O.E.M.', 'systemVersion': '1.0', 'systemUUID': '00000000-0000-0000-0000-D43D7E4F1D65', 'systemManufacturer': 'MSI'}}
Thread-15::DEBUG::2013-03-20 21:41:49,461::BindingXMLRPC::913::vds::(wrapper) client [10.100.101.108]::call getCapabilities with () {}
Thread-15::DEBUG::2013-03-20 21:41:49,478::BindingXMLRPC::920::vds::(wrapper) return getCapabilities with {'status': {'message': 'Done', 'code': 0}, 'info': {'HBAInventory': {'iSCSI': [{'InitiatorName': 'iqn.1994-05.com.redhat:1031ba876b77'}], 'FC': []}, 'packages2': {'kernel': {'release': '4.fc18.x86_64', 'buildtime': 1355241687.0, 'version': '3.6.10'}, 'spice-server': {'release': '1.fc18', 'buildtime': 1348825855L, 'version': '0.12.0'}, 'vdsm': {'release': '7.fc18', 'buildtime': 1360864703L, 'version': '4.10.3'}, 'qemu-kvm': {'release': '6.fc18', 'buildtime': 1359843954L, 'version': '1.2.2'}, 'libvirt': {'release': '1.fc18', 'buildtime': 1359405439L, 'version': '0.10.2.3'}, 'qemu-img': {'release': '6.fc18', 'buildtime': 1359843954L, 'version': '1.2.2'}, 'mom': {'release': '1.fc18', 'buildtime': 1349470214L, 'version': '0.3.0'}}, 'cpuModel': 'Intel(R) Core(TM) i5-3470 CPU @ 3.20GHz', 'hooks': {}, 'cpuSockets': '1', 'vmTypes': ['kvm'], 'supportedProtocols': ['2.2', '2.3'], 'networks': {'ovirtmgmt': {'iface': 'ovirtmgmt', 'addr': '10.100.101.108', 'cfg': {'DEVICE': 'ovirtmgmt', 'DELAY': '0', 'BOOTPROTO': 'dhcp', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '255.255.255.0', 'stp': 'off', 'bridged': True, 'gateway': '10.100.101.1', 'ports': ['p1p1']}}, 'bridges': {'ovirtmgmt': {'addr': '10.100.101.108', 'cfg': {'DEVICE': 'ovirtmgmt', 'DELAY': '0', 'BOOTPROTO': 'dhcp', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '255.255.255.0', 'stp': 'off', 'ports': ['p1p1']}}, 'uuid': '00000000-0000-0000-0000-D43D7E4F1D65_d4:3d:7e:4f:1d:65', 'lastClientIface': 'ovirtmgmt', 'nics': {'p1p1': {'addr': '', 'cfg': {'DEVICE': 'p1p1', 'BRIDGE': 'ovirtmgmt', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '', 'hwaddr': 'd4:3d:7e:4f:1d:65', 'speed': 100}}, 'software_revision': '7', 'clusterLevels': ['3.0', '3.1', '3.2'], '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,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,sse4_1,sse4_2,x2apic,popcnt,tsc_deadline_timer,aes,xsave,avx,f16c,rdrand,lahf_lm,ida,arat,epb,xsaveopt,pln,pts,dtherm,tpr_shadow,vnmi,flexpriority,ept,vpid,fsgsbase,smep,erms,model_Nehalem,model_Conroe,model_coreduo,model_core2duo,model_Penryn,model_Westmere,model_n270,model_SandyBridge', 'ISCSIInitiatorName': 'iqn.1994-05.com.redhat:1031ba876b77', 'netConfigDirty': 'False', 'supportedENGINEs': ['3.0', '3.1'], 'reservedMem': '321', 'bondings': {}, 'software_version': '4.10', 'memSize': '15916', 'cpuSpeed': '1600.000', 'version_name': 'Snow Man', 'vlans': {}, 'cpuCores': '4', 'kvmEnabled': 'true', 'guestOverhead': '65', 'management_ip': '', 'cpuThreads': '4', 'emulatedMachines': [u'pc-1.2', u'none', u'pc', u'pc-1.1', u'pc-1.0', u'pc-0.15', u'pc-0.14', u'pc-0.13', u'pc-0.12', u'pc-0.11', u'pc-0.10', u'isapc', u'pc-1.2', u'none', u'pc', u'pc-1.1', u'pc-1.0', u'pc-0.15', 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': '18', 'name': 'Fedora'}, 'lastClient': '10.100.101.108'}}
Thread-16::DEBUG::2013-03-20 21:41:49,487::BindingXMLRPC::913::vds::(wrapper) client [10.100.101.108]::call getHardwareInfo with () {}
Thread-16::DEBUG::2013-03-20 21:41:49,491::BindingXMLRPC::920::vds::(wrapper) return getHardwareInfo with {'status': {'message': 'Done', 'code': 0}, 'info': {'systemProductName': 'MS-7808', 'systemSerialNumber': 'To be filled by O.E.M.', 'systemFamily': 'To be filled by O.E.M.', 'systemVersion': '1.0', 'systemUUID': '00000000-0000-0000-0000-D43D7E4F1D65', 'systemManufacturer': 'MSI'}}
Thread-22::DEBUG::2013-03-20 21:41:59,825::task::568::TaskManager.Task::(_updateState) Task=`d54cd8ef-d6bd-47a5-859f-27b5f8b650af`::moving from state init -> state preparing
Thread-22::INFO::2013-03-20 21:41:59,826::logUtils::41::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-22::INFO::2013-03-20 21:41:59,826::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-22::DEBUG::2013-03-20 21:41:59,826::task::1151::TaskManager.Task::(prepare) Task=`d54cd8ef-d6bd-47a5-859f-27b5f8b650af`::finished: {}
Thread-22::DEBUG::2013-03-20 21:41:59,826::task::568::TaskManager.Task::(_updateState) Task=`d54cd8ef-d6bd-47a5-859f-27b5f8b650af`::moving from state preparing -> state finished
Thread-22::DEBUG::2013-03-20 21:41:59,826::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-22::DEBUG::2013-03-20 21:41:59,826::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-22::DEBUG::2013-03-20 21:41:59,827::task::957::TaskManager.Task::(_decref) Task=`d54cd8ef-d6bd-47a5-859f-27b5f8b650af`::ref 0 aborting False
Thread-28::DEBUG::2013-03-20 21:42:10,020::task::568::TaskManager.Task::(_updateState) Task=`3b7d0654-b3ea-4562-9d60-878869a2460c`::moving from state init -> state preparing
Thread-28::INFO::2013-03-20 21:42:10,021::logUtils::41::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-28::INFO::2013-03-20 21:42:10,021::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-28::DEBUG::2013-03-20 21:42:10,021::task::1151::TaskManager.Task::(prepare) Task=`3b7d0654-b3ea-4562-9d60-878869a2460c`::finished: {}
Thread-28::DEBUG::2013-03-20 21:42:10,021::task::568::TaskManager.Task::(_updateState) Task=`3b7d0654-b3ea-4562-9d60-878869a2460c`::moving from state preparing -> state finished
Thread-28::DEBUG::2013-03-20 21:42:10,021::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-28::DEBUG::2013-03-20 21:42:10,021::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-28::DEBUG::2013-03-20 21:42:10,022::task::957::TaskManager.Task::(_decref) Task=`3b7d0654-b3ea-4562-9d60-878869a2460c`::ref 0 aborting False
Thread-34::DEBUG::2013-03-20 21:42:20,126::task::568::TaskManager.Task::(_updateState) Task=`7ed7caa9-1f8d-4dac-b8b7-22e25a7b713f`::moving from state init -> state preparing
Thread-34::INFO::2013-03-20 21:42:20,126::logUtils::41::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-34::INFO::2013-03-20 21:42:20,126::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-34::DEBUG::2013-03-20 21:42:20,126::task::1151::TaskManager.Task::(prepare) Task=`7ed7caa9-1f8d-4dac-b8b7-22e25a7b713f`::finished: {}
Thread-34::DEBUG::2013-03-20 21:42:20,127::task::568::TaskManager.Task::(_updateState) Task=`7ed7caa9-1f8d-4dac-b8b7-22e25a7b713f`::moving from state preparing -> state finished
Thread-34::DEBUG::2013-03-20 21:42:20,127::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-34::DEBUG::2013-03-20 21:42:20,127::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-34::DEBUG::2013-03-20 21:42:20,127::task::957::TaskManager.Task::(_decref) Task=`7ed7caa9-1f8d-4dac-b8b7-22e25a7b713f`::ref 0 aborting False
Thread-40::DEBUG::2013-03-20 21:42:30,192::task::568::TaskManager.Task::(_updateState) Task=`7d10c1f7-516b-4169-aacb-9e9dcebe0128`::moving from state init -> state preparing
Thread-40::INFO::2013-03-20 21:42:30,193::logUtils::41::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-40::INFO::2013-03-20 21:42:30,193::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-40::DEBUG::2013-03-20 21:42:30,193::task::1151::TaskManager.Task::(prepare) Task=`7d10c1f7-516b-4169-aacb-9e9dcebe0128`::finished: {}
Thread-40::DEBUG::2013-03-20 21:42:30,193::task::568::TaskManager.Task::(_updateState) Task=`7d10c1f7-516b-4169-aacb-9e9dcebe0128`::moving from state preparing -> state finished
Thread-40::DEBUG::2013-03-20 21:42:30,193::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-40::DEBUG::2013-03-20 21:42:30,193::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-40::DEBUG::2013-03-20 21:42:30,193::task::957::TaskManager.Task::(_decref) Task=`7d10c1f7-516b-4169-aacb-9e9dcebe0128`::ref 0 aborting False
Thread-46::DEBUG::2013-03-20 21:42:40,259::task::568::TaskManager.Task::(_updateState) Task=`a766ec5e-0ea0-4e7e-88e2-fb7212f76384`::moving from state init -> state preparing
Thread-46::INFO::2013-03-20 21:42:40,260::logUtils::41::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-46::INFO::2013-03-20 21:42:40,260::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-46::DEBUG::2013-03-20 21:42:40,260::task::1151::TaskManager.Task::(prepare) Task=`a766ec5e-0ea0-4e7e-88e2-fb7212f76384`::finished: {}
Thread-46::DEBUG::2013-03-20 21:42:40,260::task::568::TaskManager.Task::(_updateState) Task=`a766ec5e-0ea0-4e7e-88e2-fb7212f76384`::moving from state preparing -> state finished
Thread-46::DEBUG::2013-03-20 21:42:40,260::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-46::DEBUG::2013-03-20 21:42:40,260::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-46::DEBUG::2013-03-20 21:42:40,261::task::957::TaskManager.Task::(_decref) Task=`a766ec5e-0ea0-4e7e-88e2-fb7212f76384`::ref 0 aborting False
Thread-52::DEBUG::2013-03-20 21:42:50,328::task::568::TaskManager.Task::(_updateState) Task=`51ec1057-529d-4a3c-a915-4ad90e427bb2`::moving from state init -> state preparing
Thread-52::INFO::2013-03-20 21:42:50,329::logUtils::41::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-52::INFO::2013-03-20 21:42:50,329::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-52::DEBUG::2013-03-20 21:42:50,329::task::1151::TaskManager.Task::(prepare) Task=`51ec1057-529d-4a3c-a915-4ad90e427bb2`::finished: {}
Thread-52::DEBUG::2013-03-20 21:42:50,329::task::568::TaskManager.Task::(_updateState) Task=`51ec1057-529d-4a3c-a915-4ad90e427bb2`::moving from state preparing -> state finished
Thread-52::DEBUG::2013-03-20 21:42:50,329::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-52::DEBUG::2013-03-20 21:42:50,329::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-52::DEBUG::2013-03-20 21:42:50,330::task::957::TaskManager.Task::(_decref) Task=`51ec1057-529d-4a3c-a915-4ad90e427bb2`::ref 0 aborting False
Thread-58::DEBUG::2013-03-20 21:43:00,392::task::568::TaskManager.Task::(_updateState) Task=`d6354c30-de2d-4d60-adff-5618f9ef86c5`::moving from state init -> state preparing
Thread-58::INFO::2013-03-20 21:43:00,392::logUtils::41::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-58::INFO::2013-03-20 21:43:00,392::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-58::DEBUG::2013-03-20 21:43:00,393::task::1151::TaskManager.Task::(prepare) Task=`d6354c30-de2d-4d60-adff-5618f9ef86c5`::finished: {}
Thread-58::DEBUG::2013-03-20 21:43:00,393::task::568::TaskManager.Task::(_updateState) Task=`d6354c30-de2d-4d60-adff-5618f9ef86c5`::moving from state preparing -> state finished
Thread-58::DEBUG::2013-03-20 21:43:00,393::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-58::DEBUG::2013-03-20 21:43:00,393::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-58::DEBUG::2013-03-20 21:43:00,393::task::957::TaskManager.Task::(_decref) Task=`d6354c30-de2d-4d60-adff-5618f9ef86c5`::ref 0 aborting False
Thread-64::DEBUG::2013-03-20 21:43:10,527::task::568::TaskManager.Task::(_updateState) Task=`cee3172b-c418-41af-81a5-23fe91f30f0c`::moving from state init -> state preparing
Thread-64::INFO::2013-03-20 21:43:10,528::logUtils::41::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-64::INFO::2013-03-20 21:43:10,528::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-64::DEBUG::2013-03-20 21:43:10,528::task::1151::TaskManager.Task::(prepare) Task=`cee3172b-c418-41af-81a5-23fe91f30f0c`::finished: {}
Thread-64::DEBUG::2013-03-20 21:43:10,528::task::568::TaskManager.Task::(_updateState) Task=`cee3172b-c418-41af-81a5-23fe91f30f0c`::moving from state preparing -> state finished
Thread-64::DEBUG::2013-03-20 21:43:10,528::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-64::DEBUG::2013-03-20 21:43:10,528::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-64::DEBUG::2013-03-20 21:43:10,529::task::957::TaskManager.Task::(_decref) Task=`cee3172b-c418-41af-81a5-23fe91f30f0c`::ref 0 aborting False
Thread-70::DEBUG::2013-03-20 21:43:20,598::task::568::TaskManager.Task::(_updateState) Task=`cc1aa874-19db-405e-801a-bf82e0d3e445`::moving from state init -> state preparing
Thread-70::INFO::2013-03-20 21:43:20,598::logUtils::41::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-70::INFO::2013-03-20 21:43:20,598::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-70::DEBUG::2013-03-20 21:43:20,599::task::1151::TaskManager.Task::(prepare) Task=`cc1aa874-19db-405e-801a-bf82e0d3e445`::finished: {}
Thread-70::DEBUG::2013-03-20 21:43:20,599::task::568::TaskManager.Task::(_updateState) Task=`cc1aa874-19db-405e-801a-bf82e0d3e445`::moving from state preparing -> state finished
Thread-70::DEBUG::2013-03-20 21:43:20,599::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-70::DEBUG::2013-03-20 21:43:20,599::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-70::DEBUG::2013-03-20 21:43:20,599::task::957::TaskManager.Task::(_decref) Task=`cc1aa874-19db-405e-801a-bf82e0d3e445`::ref 0 aborting False
Thread-76::DEBUG::2013-03-20 21:43:30,660::task::568::TaskManager.Task::(_updateState) Task=`b75cb69f-ff85-4215-800c-5f1ee7ce0f6e`::moving from state init -> state preparing
Thread-76::INFO::2013-03-20 21:43:30,661::logUtils::41::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-76::INFO::2013-03-20 21:43:30,661::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-76::DEBUG::2013-03-20 21:43:30,661::task::1151::TaskManager.Task::(prepare) Task=`b75cb69f-ff85-4215-800c-5f1ee7ce0f6e`::finished: {}
Thread-76::DEBUG::2013-03-20 21:43:30,661::task::568::TaskManager.Task::(_updateState) Task=`b75cb69f-ff85-4215-800c-5f1ee7ce0f6e`::moving from state preparing -> state finished
Thread-76::DEBUG::2013-03-20 21:43:30,661::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-76::DEBUG::2013-03-20 21:43:30,661::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-76::DEBUG::2013-03-20 21:43:30,661::task::957::TaskManager.Task::(_decref) Task=`b75cb69f-ff85-4215-800c-5f1ee7ce0f6e`::ref 0 aborting False
Thread-82::DEBUG::2013-03-20 21:43:40,722::task::568::TaskManager.Task::(_updateState) Task=`8de715ae-3804-49a7-a664-aba049cee807`::moving from state init -> state preparing
Thread-82::INFO::2013-03-20 21:43:40,722::logUtils::41::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-82::INFO::2013-03-20 21:43:40,722::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-82::DEBUG::2013-03-20 21:43:40,722::task::1151::TaskManager.Task::(prepare) Task=`8de715ae-3804-49a7-a664-aba049cee807`::finished: {}
Thread-82::DEBUG::2013-03-20 21:43:40,723::task::568::TaskManager.Task::(_updateState) Task=`8de715ae-3804-49a7-a664-aba049cee807`::moving from state preparing -> state finished
Thread-82::DEBUG::2013-03-20 21:43:40,723::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-82::DEBUG::2013-03-20 21:43:40,723::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-82::DEBUG::2013-03-20 21:43:40,723::task::957::TaskManager.Task::(_decref) Task=`8de715ae-3804-49a7-a664-aba049cee807`::ref 0 aborting False
Thread-88::DEBUG::2013-03-20 21:43:50,785::task::568::TaskManager.Task::(_updateState) Task=`16f3e49a-faba-4790-9d9b-13c3e2982107`::moving from state init -> state preparing
Thread-88::INFO::2013-03-20 21:43:50,786::logUtils::41::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-88::INFO::2013-03-20 21:43:50,786::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-88::DEBUG::2013-03-20 21:43:50,786::task::1151::TaskManager.Task::(prepare) Task=`16f3e49a-faba-4790-9d9b-13c3e2982107`::finished: {}
Thread-88::DEBUG::2013-03-20 21:43:50,786::task::568::TaskManager.Task::(_updateState) Task=`16f3e49a-faba-4790-9d9b-13c3e2982107`::moving from state preparing -> state finished
Thread-88::DEBUG::2013-03-20 21:43:50,786::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-88::DEBUG::2013-03-20 21:43:50,787::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-88::DEBUG::2013-03-20 21:43:50,787::task::957::TaskManager.Task::(_decref) Task=`16f3e49a-faba-4790-9d9b-13c3e2982107`::ref 0 aborting False
Thread-94::DEBUG::2013-03-20 21:44:00,847::task::568::TaskManager.Task::(_updateState) Task=`540e2196-42d9-4f0a-9ef0-290892ec3db9`::moving from state init -> state preparing
Thread-94::INFO::2013-03-20 21:44:00,847::logUtils::41::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-94::INFO::2013-03-20 21:44:00,847::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-94::DEBUG::2013-03-20 21:44:00,847::task::1151::TaskManager.Task::(prepare) Task=`540e2196-42d9-4f0a-9ef0-290892ec3db9`::finished: {}
Thread-94::DEBUG::2013-03-20 21:44:00,848::task::568::TaskManager.Task::(_updateState) Task=`540e2196-42d9-4f0a-9ef0-290892ec3db9`::moving from state preparing -> state finished
Thread-94::DEBUG::2013-03-20 21:44:00,848::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-94::DEBUG::2013-03-20 21:44:00,848::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-94::DEBUG::2013-03-20 21:44:00,848::task::957::TaskManager.Task::(_decref) Task=`540e2196-42d9-4f0a-9ef0-290892ec3db9`::ref 0 aborting False
Thread-100::DEBUG::2013-03-20 21:44:10,942::task::568::TaskManager.Task::(_updateState) Task=`a19d0627-5539-4138-a4cf-f149f88cb6c7`::moving from state init -> state preparing
Thread-100::INFO::2013-03-20 21:44:10,943::logUtils::41::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-100::INFO::2013-03-20 21:44:10,943::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-100::DEBUG::2013-03-20 21:44:10,943::task::1151::TaskManager.Task::(prepare) Task=`a19d0627-5539-4138-a4cf-f149f88cb6c7`::finished: {}
Thread-100::DEBUG::2013-03-20 21:44:10,943::task::568::TaskManager.Task::(_updateState) Task=`a19d0627-5539-4138-a4cf-f149f88cb6c7`::moving from state preparing -> state finished
Thread-100::DEBUG::2013-03-20 21:44:10,943::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-100::DEBUG::2013-03-20 21:44:10,944::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-100::DEBUG::2013-03-20 21:44:10,944::task::957::TaskManager.Task::(_decref) Task=`a19d0627-5539-4138-a4cf-f149f88cb6c7`::ref 0 aborting False
Thread-106::DEBUG::2013-03-20 21:44:21,125::task::568::TaskManager.Task::(_updateState) Task=`bab57f3a-2756-4729-bac4-fd8940220638`::moving from state init -> state preparing
Thread-106::INFO::2013-03-20 21:44:21,126::logUtils::41::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-106::INFO::2013-03-20 21:44:21,126::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-106::DEBUG::2013-03-20 21:44:21,126::task::1151::TaskManager.Task::(prepare) Task=`bab57f3a-2756-4729-bac4-fd8940220638`::finished: {}
Thread-106::DEBUG::2013-03-20 21:44:21,126::task::568::TaskManager.Task::(_updateState) Task=`bab57f3a-2756-4729-bac4-fd8940220638`::moving from state preparing -> state finished
Thread-106::DEBUG::2013-03-20 21:44:21,127::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-106::DEBUG::2013-03-20 21:44:21,127::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-106::DEBUG::2013-03-20 21:44:21,127::task::957::TaskManager.Task::(_decref) Task=`bab57f3a-2756-4729-bac4-fd8940220638`::ref 0 aborting False
Thread-111::DEBUG::2013-03-20 21:44:29,136::BindingXMLRPC::161::vds::(wrapper) [10.100.101.108]
Thread-111::DEBUG::2013-03-20 21:44:29,137::task::568::TaskManager.Task::(_updateState) Task=`06b0f6f8-0270-485f-91f7-3c62f038c2c4`::moving from state init -> state preparing
Thread-111::INFO::2013-03-20 21:44:29,137::logUtils::41::dispatcher::(wrapper) Run and protect: validateStorageServerConnection(domType=1, spUUID='00000000-0000-0000-0000-000000000000', conList=[{'connection': 'bufferoverflow.home:/BO_Ovirt_Storage', 'iqn': '', 'portal': '', 'user': '', 'password': '******', 'id': '00000000-0000-0000-0000-000000000000', 'port': ''}], options=None)
Thread-111::INFO::2013-03-20 21:44:29,137::logUtils::44::dispatcher::(wrapper) Run and protect: validateStorageServerConnection, Return response: {'statuslist': [{'status': 0, 'id': '00000000-0000-0000-0000-000000000000'}]}
Thread-111::DEBUG::2013-03-20 21:44:29,137::task::1151::TaskManager.Task::(prepare) Task=`06b0f6f8-0270-485f-91f7-3c62f038c2c4`::finished: {'statuslist': [{'status': 0, 'id': '00000000-0000-0000-0000-000000000000'}]}
Thread-111::DEBUG::2013-03-20 21:44:29,137::task::568::TaskManager.Task::(_updateState) Task=`06b0f6f8-0270-485f-91f7-3c62f038c2c4`::moving from state preparing -> state finished
Thread-111::DEBUG::2013-03-20 21:44:29,137::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-111::DEBUG::2013-03-20 21:44:29,138::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-111::DEBUG::2013-03-20 21:44:29,138::task::957::TaskManager.Task::(_decref) Task=`06b0f6f8-0270-485f-91f7-3c62f038c2c4`::ref 0 aborting False
Thread-112::DEBUG::2013-03-20 21:44:29,153::BindingXMLRPC::161::vds::(wrapper) [10.100.101.108]
Thread-112::DEBUG::2013-03-20 21:44:29,154::task::568::TaskManager.Task::(_updateState) Task=`49bd50e6-bcec-40af-b27b-3ff8cd2846ce`::moving from state init -> state preparing
Thread-112::INFO::2013-03-20 21:44:29,154::logUtils::41::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=1, spUUID='00000000-0000-0000-0000-000000000000', conList=[{'connection': 'bufferoverflow.home:/BO_Ovirt_Storage', 'iqn': '', 'portal': '', 'user': '', 'password': '******', 'id': '00000000-0000-0000-0000-000000000000', 'port': ''}], options=None)
Thread-112::DEBUG::2013-03-20 21:44:29,157::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/sudo -n /usr/bin/mount -t nfs -o soft,nosharecache,timeo=600,retrans=6,nfsvers=3 bufferoverflow.home:/BO_Ovirt_Storage /rhev/data-center/mnt/bufferoverflow.home:_BO__Ovirt__Storage' (cwd None)
Thread-112::ERROR::2013-03-20 21:44:29,223::hsm::2215::Storage.HSM::(connectStorageServer) Could not connect to storageServer
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/hsm.py", line 2211, in connectStorageServer
    conObj.connect()
  File "/usr/share/vdsm/storage/storageServer.py", line 302, in connect
    return self._mountCon.connect()
  File "/usr/share/vdsm/storage/storageServer.py", line 208, in connect
    fileSD.validateDirAccess(self.getMountObj().getRecord().fs_file)
  File "/usr/share/vdsm/storage/mount.py", line 260, in getRecord
    (self.fs_spec, self.fs_file))
OSError: [Errno 2] Mount of `bufferoverflow.home:/BO_Ovirt_Storage` at `/rhev/data-center/mnt/bufferoverflow.home:_BO__Ovirt__Storage` does not exist
Thread-112::INFO::2013-03-20 21:44:29,224::logUtils::44::dispatcher::(wrapper) Run and protect: connectStorageServer, Return response: {'statuslist': [{'status': 100, 'id': '00000000-0000-0000-0000-000000000000'}]}
Thread-112::DEBUG::2013-03-20 21:44:29,224::task::1151::TaskManager.Task::(prepare) Task=`49bd50e6-bcec-40af-b27b-3ff8cd2846ce`::finished: {'statuslist': [{'status': 100, 'id': '00000000-0000-0000-0000-000000000000'}]}
Thread-112::DEBUG::2013-03-20 21:44:29,225::task::568::TaskManager.Task::(_updateState) Task=`49bd50e6-bcec-40af-b27b-3ff8cd2846ce`::moving from state preparing -> state finished
Thread-112::DEBUG::2013-03-20 21:44:29,225::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-112::DEBUG::2013-03-20 21:44:29,225::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-112::DEBUG::2013-03-20 21:44:29,225::task::957::TaskManager.Task::(_decref) Task=`49bd50e6-bcec-40af-b27b-3ff8cd2846ce`::ref 0 aborting False
Thread-114::DEBUG::2013-03-20 21:44:29,666::BindingXMLRPC::161::vds::(wrapper) [10.100.101.108]
Thread-114::DEBUG::2013-03-20 21:44:29,667::task::568::TaskManager.Task::(_updateState) Task=`d25d3f7a-ac16-47d4-aa44-2a7e051256b0`::moving from state init -> state preparing
Thread-114::INFO::2013-03-20 21:44:29,667::logUtils::41::dispatcher::(wrapper) Run and protect: disconnectStorageServer(domType=1, spUUID='00000000-0000-0000-0000-000000000000', conList=[{'connection': 'bufferoverflow.home:/BO_Ovirt_Storage', 'iqn': '', 'portal': '', 'user': '', 'password': '******', 'id': '00000000-0000-0000-0000-000000000000', 'port': ''}], options=None)
Thread-114::DEBUG::2013-03-20 21:44:29,668::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/sudo -n /usr/bin/umount -f -l /rhev/data-center/mnt/bufferoverflow.home:_BO__Ovirt__Storage' (cwd None)
Thread-114::ERROR::2013-03-20 21:44:29,683::hsm::2295::Storage.HSM::(disconnectStorageServer) Could not disconnect from storageServer
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/hsm.py", line 2291, in disconnectStorageServer
    conObj.disconnect()
  File "/usr/share/vdsm/storage/storageServer.py", line 308, in disconnect
    return self._mountCon.disconnect()
  File "/usr/share/vdsm/storage/storageServer.py", line 221, in disconnect
    self._mount.umount(True, True)
  File "/usr/share/vdsm/storage/mount.py", line 242, in umount
    return self._runcmd(cmd, timeout)
  File "/usr/share/vdsm/storage/mount.py", line 230, in _runcmd
    raise MountError(rc, ";".join((out, err)))
MountError: (32, ';umount: /rhev/data-center/mnt/bufferoverflow.home:_BO__Ovirt__Storage: not found\n')
Thread-114::DEBUG::2013-03-20 21:44:29,683::misc::1054::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
Thread-114::DEBUG::2013-03-20 21:44:29,684::misc::1056::SamplingMethod::(__call__) Got in to sampling method
Thread-114::DEBUG::2013-03-20 21:44:29,684::misc::1054::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
Thread-114::DEBUG::2013-03-20 21:44:29,684::misc::1056::SamplingMethod::(__call__) Got in to sampling method
Thread-114::DEBUG::2013-03-20 21:44:29,684::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
Thread-114::DEBUG::2013-03-20 21:44:29,698::misc::84::Storage.Misc.excCmd::(<lambda>) FAILED: <err> = 'iscsiadm: No session found.\n'; <rc> = 21
Thread-114::DEBUG::2013-03-20 21:44:29,699::misc::1064::SamplingMethod::(__call__) Returning last result
MainProcess|Thread-114::DEBUG::2013-03-20 21:44:29,701::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/dd of=/sys/class/scsi_host/host0/scan' (cwd None)
MainProcess|Thread-114::DEBUG::2013-03-20 21:44:30,705::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/dd of=/sys/class/scsi_host/host1/scan' (cwd None)
MainProcess|Thread-114::DEBUG::2013-03-20 21:44:30,709::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/dd of=/sys/class/scsi_host/host2/scan' (cwd None)
Thread-115::DEBUG::2013-03-20 21:44:31,216::task::568::TaskManager.Task::(_updateState) Task=`45106f0c-e96c-46e2-bbd2-3f75eef1922f`::moving from state init -> state preparing
Thread-115::INFO::2013-03-20 21:44:31,216::logUtils::41::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-115::INFO::2013-03-20 21:44:31,217::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-115::DEBUG::2013-03-20 21:44:31,217::task::1151::TaskManager.Task::(prepare) Task=`45106f0c-e96c-46e2-bbd2-3f75eef1922f`::finished: {}
Thread-115::DEBUG::2013-03-20 21:44:31,217::task::568::TaskManager.Task::(_updateState) Task=`45106f0c-e96c-46e2-bbd2-3f75eef1922f`::moving from state preparing -> state finished
Thread-115::DEBUG::2013-03-20 21:44:31,217::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-115::DEBUG::2013-03-20 21:44:31,217::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-115::DEBUG::2013-03-20 21:44:31,217::task::957::TaskManager.Task::(_decref) Task=`45106f0c-e96c-46e2-bbd2-3f75eef1922f`::ref 0 aborting False
MainProcess|Thread-114::DEBUG::2013-03-20 21:44:31,713::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/dd of=/sys/class/scsi_host/host3/scan' (cwd None)
MainProcess|Thread-114::DEBUG::2013-03-20 21:44:32,718::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/dd of=/sys/class/scsi_host/host4/scan' (cwd None)
MainProcess|Thread-114::DEBUG::2013-03-20 21:44:32,721::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/dd of=/sys/class/scsi_host/host5/scan' (cwd None)
MainProcess|Thread-114::DEBUG::2013-03-20 21:44:32,724::iscsi::402::Storage.ISCSI::(forceIScsiScan) Performing SCSI scan, this will take up to 30 seconds
Thread-114::DEBUG::2013-03-20 21:44:34,726::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/sudo -n /sbin/multipath' (cwd None)
Thread-114::DEBUG::2013-03-20 21:44:34,749::misc::84::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> = ''; <rc> = 0
Thread-114::DEBUG::2013-03-20 21:44:34,750::lvm::477::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-114::DEBUG::2013-03-20 21:44:34,750::lvm::479::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-114::DEBUG::2013-03-20 21:44:34,750::lvm::488::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
Thread-114::DEBUG::2013-03-20 21:44:34,751::lvm::490::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
Thread-114::DEBUG::2013-03-20 21:44:34,751::lvm::508::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-114::DEBUG::2013-03-20 21:44:34,751::lvm::510::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-114::DEBUG::2013-03-20 21:44:34,752::misc::1064::SamplingMethod::(__call__) Returning last result
Thread-114::INFO::2013-03-20 21:44:34,752::logUtils::44::dispatcher::(wrapper) Run and protect: disconnectStorageServer, Return response: {'statuslist': [{'status': 477, 'id': '00000000-0000-0000-0000-000000000000'}]}
Thread-114::DEBUG::2013-03-20 21:44:34,752::task::1151::TaskManager.Task::(prepare) Task=`d25d3f7a-ac16-47d4-aa44-2a7e051256b0`::finished: {'statuslist': [{'status': 477, 'id': '00000000-0000-0000-0000-000000000000'}]}
Thread-114::DEBUG::2013-03-20 21:44:34,753::task::568::TaskManager.Task::(_updateState) Task=`d25d3f7a-ac16-47d4-aa44-2a7e051256b0`::moving from state preparing -> state finished
Thread-114::DEBUG::2013-03-20 21:44:34,753::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-114::DEBUG::2013-03-20 21:44:34,753::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-114::DEBUG::2013-03-20 21:44:34,753::task::957::TaskManager.Task::(_decref) Task=`d25d3f7a-ac16-47d4-aa44-2a7e051256b0`::ref 0 aborting False
Thread-121::DEBUG::2013-03-20 21:44:41,279::task::568::TaskManager.Task::(_updateState) Task=`0d544b9a-12b8-4eec-a532-b896781ae1ab`::moving from state init -> state preparing
Thread-121::INFO::2013-03-20 21:44:41,280::logUtils::41::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-121::INFO::2013-03-20 21:44:41,280::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-121::DEBUG::2013-03-20 21:44:41,280::task::1151::TaskManager.Task::(prepare) Task=`0d544b9a-12b8-4eec-a532-b896781ae1ab`::finished: {}
Thread-121::DEBUG::2013-03-20 21:44:41,280::task::568::TaskManager.Task::(_updateState) Task=`0d544b9a-12b8-4eec-a532-b896781ae1ab`::moving from state preparing -> state finished
Thread-121::DEBUG::2013-03-20 21:44:41,281::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-121::DEBUG::2013-03-20 21:44:41,281::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-121::DEBUG::2013-03-20 21:44:41,281::task::957::TaskManager.Task::(_decref) Task=`0d544b9a-12b8-4eec-a532-b896781ae1ab`::ref 0 aborting False
Thread-127::DEBUG::2013-03-20 21:44:51,341::task::568::TaskManager.Task::(_updateState) Task=`cd537287-cb6e-482a-9c6e-a176e644facc`::moving from state init -> state preparing
Thread-127::INFO::2013-03-20 21:44:51,341::logUtils::41::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-127::INFO::2013-03-20 21:44:51,342::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-127::DEBUG::2013-03-20 21:44:51,342::task::1151::TaskManager.Task::(prepare) Task=`cd537287-cb6e-482a-9c6e-a176e644facc`::finished: {}
Thread-127::DEBUG::2013-03-20 21:44:51,342::task::568::TaskManager.Task::(_updateState) Task=`cd537287-cb6e-482a-9c6e-a176e644facc`::moving from state preparing -> state finished
Thread-127::DEBUG::2013-03-20 21:44:51,342::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-127::DEBUG::2013-03-20 21:44:51,342::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-127::DEBUG::2013-03-20 21:44:51,342::task::957::TaskManager.Task::(_decref) Task=`cd537287-cb6e-482a-9c6e-a176e644facc`::ref 0 aborting False
Thread-133::DEBUG::2013-03-20 21:45:01,402::task::568::TaskManager.Task::(_updateState) Task=`0ffbae58-e663-4ee1-b342-cba7020bef9e`::moving from state init -> state preparing
Thread-133::INFO::2013-03-20 21:45:01,402::logUtils::41::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-133::INFO::2013-03-20 21:45:01,402::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-133::DEBUG::2013-03-20 21:45:01,403::task::1151::TaskManager.Task::(prepare) Task=`0ffbae58-e663-4ee1-b342-cba7020bef9e`::finished: {}
Thread-133::DEBUG::2013-03-20 21:45:01,403::task::568::TaskManager.Task::(_updateState) Task=`0ffbae58-e663-4ee1-b342-cba7020bef9e`::moving from state preparing -> state finished
Thread-133::DEBUG::2013-03-20 21:45:01,403::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-133::DEBUG::2013-03-20 21:45:01,403::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-133::DEBUG::2013-03-20 21:45:01,403::task::957::TaskManager.Task::(_decref) Task=`0ffbae58-e663-4ee1-b342-cba7020bef9e`::ref 0 aborting False
Thread-136::DEBUG::2013-03-20 21:45:03,544::BindingXMLRPC::161::vds::(wrapper) [10.100.101.108]
Thread-136::DEBUG::2013-03-20 21:45:03,545::task::568::TaskManager.Task::(_updateState) Task=`a053ac71-babc-4b8c-90d2-71c529cc5d87`::moving from state init -> state preparing
Thread-136::INFO::2013-03-20 21:45:03,545::logUtils::41::dispatcher::(wrapper) Run and protect: validateStorageServerConnection(domType=1, spUUID='00000000-0000-0000-0000-000000000000', conList=[{'connection': 'bufferoverflow.home:/home/BO_Ovirt_Storage', 'iqn': '', 'portal': '', 'user': '', 'password': '******', 'id': '00000000-0000-0000-0000-000000000000', 'port': ''}], options=None)
Thread-136::INFO::2013-03-20 21:45:03,545::logUtils::44::dispatcher::(wrapper) Run and protect: validateStorageServerConnection, Return response: {'statuslist': [{'status': 0, 'id': '00000000-0000-0000-0000-000000000000'}]}
Thread-136::DEBUG::2013-03-20 21:45:03,545::task::1151::TaskManager.Task::(prepare) Task=`a053ac71-babc-4b8c-90d2-71c529cc5d87`::finished: {'statuslist': [{'status': 0, 'id': '00000000-0000-0000-0000-000000000000'}]}
Thread-136::DEBUG::2013-03-20 21:45:03,545::task::568::TaskManager.Task::(_updateState) Task=`a053ac71-babc-4b8c-90d2-71c529cc5d87`::moving from state preparing -> state finished
Thread-136::DEBUG::2013-03-20 21:45:03,546::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-136::DEBUG::2013-03-20 21:45:03,546::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-136::DEBUG::2013-03-20 21:45:03,546::task::957::TaskManager.Task::(_decref) Task=`a053ac71-babc-4b8c-90d2-71c529cc5d87`::ref 0 aborting False
Thread-137::DEBUG::2013-03-20 21:45:03,564::BindingXMLRPC::161::vds::(wrapper) [10.100.101.108]
Thread-137::DEBUG::2013-03-20 21:45:03,564::task::568::TaskManager.Task::(_updateState) Task=`3413c734-7bad-4cc6-958c-4f89cf8200d6`::moving from state init -> state preparing
Thread-137::INFO::2013-03-20 21:45:03,565::logUtils::41::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=1, spUUID='00000000-0000-0000-0000-000000000000', conList=[{'connection': 'bufferoverflow.home:/home/BO_Ovirt_Storage', 'iqn': '', 'portal': '', 'user': '', 'password': '******', 'id': '00000000-0000-0000-0000-000000000000', 'port': ''}], options=None)
Thread-137::DEBUG::2013-03-20 21:45:03,570::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/sudo -n /usr/bin/mount -t nfs -o soft,nosharecache,timeo=600,retrans=6,nfsvers=3 bufferoverflow.home:/home/BO_Ovirt_Storage /rhev/data-center/mnt/bufferoverflow.home:_home_BO__Ovirt__Storage' (cwd None)
Thread-137::INFO::2013-03-20 21:45:03,691::logUtils::44::dispatcher::(wrapper) Run and protect: connectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': '00000000-0000-0000-0000-000000000000'}]}
Thread-137::DEBUG::2013-03-20 21:45:03,692::task::1151::TaskManager.Task::(prepare) Task=`3413c734-7bad-4cc6-958c-4f89cf8200d6`::finished: {'statuslist': [{'status': 0, 'id': '00000000-0000-0000-0000-000000000000'}]}
Thread-137::DEBUG::2013-03-20 21:45:03,692::task::568::TaskManager.Task::(_updateState) Task=`3413c734-7bad-4cc6-958c-4f89cf8200d6`::moving from state preparing -> state finished
Thread-137::DEBUG::2013-03-20 21:45:03,692::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-137::DEBUG::2013-03-20 21:45:03,692::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-137::DEBUG::2013-03-20 21:45:03,692::task::957::TaskManager.Task::(_decref) Task=`3413c734-7bad-4cc6-958c-4f89cf8200d6`::ref 0 aborting False
Thread-138::DEBUG::2013-03-20 21:45:03,842::BindingXMLRPC::161::vds::(wrapper) [10.100.101.108]
Thread-138::DEBUG::2013-03-20 21:45:03,843::task::568::TaskManager.Task::(_updateState) Task=`31a0ac28-1fbd-463e-afd6-fa6e64bb2f09`::moving from state init -> state preparing
Thread-138::INFO::2013-03-20 21:45:03,843::logUtils::41::dispatcher::(wrapper) Run and protect: createStorageDomain(storageType=1, sdUUID='1083422e-a5db-41b6-b667-b9ef1ef244f0', domainName='BO_data', typeSpecificArg='bufferoverflow.home:/home/BO_Ovirt_Storage', domClass=1, domVersion='3', options=None)
Thread-138::DEBUG::2013-03-20 21:45:03,843::misc::1054::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
Thread-138::DEBUG::2013-03-20 21:45:03,843::misc::1056::SamplingMethod::(__call__) Got in to sampling method
Thread-138::DEBUG::2013-03-20 21:45:03,843::misc::1054::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
Thread-138::DEBUG::2013-03-20 21:45:03,843::misc::1056::SamplingMethod::(__call__) Got in to sampling method
Thread-138::DEBUG::2013-03-20 21:45:03,843::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
Thread-138::DEBUG::2013-03-20 21:45:03,851::misc::84::Storage.Misc.excCmd::(<lambda>) FAILED: <err> = 'iscsiadm: No session found.\n'; <rc> = 21
Thread-138::DEBUG::2013-03-20 21:45:03,851::misc::1064::SamplingMethod::(__call__) Returning last result
MainProcess|Thread-138::DEBUG::2013-03-20 21:45:03,852::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/dd of=/sys/class/scsi_host/host0/scan' (cwd None)
MainProcess|Thread-138::DEBUG::2013-03-20 21:45:03,854::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/dd of=/sys/class/scsi_host/host1/scan' (cwd None)
MainProcess|Thread-138::DEBUG::2013-03-20 21:45:04,858::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/dd of=/sys/class/scsi_host/host2/scan' (cwd None)
MainProcess|Thread-138::DEBUG::2013-03-20 21:45:05,862::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/dd of=/sys/class/scsi_host/host3/scan' (cwd None)
MainProcess|Thread-138::DEBUG::2013-03-20 21:45:05,866::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/dd of=/sys/class/scsi_host/host4/scan' (cwd None)
MainProcess|Thread-138::DEBUG::2013-03-20 21:45:05,869::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/dd of=/sys/class/scsi_host/host5/scan' (cwd None)
MainProcess|Thread-138::DEBUG::2013-03-20 21:45:06,873::iscsi::402::Storage.ISCSI::(forceIScsiScan) Performing SCSI scan, this will take up to 30 seconds
Thread-138::DEBUG::2013-03-20 21:45:08,877::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/sudo -n /sbin/multipath' (cwd None)
Thread-138::DEBUG::2013-03-20 21:45:08,904::misc::84::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> = ''; <rc> = 0
Thread-138::DEBUG::2013-03-20 21:45:08,905::lvm::477::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-138::DEBUG::2013-03-20 21:45:08,905::lvm::479::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-138::DEBUG::2013-03-20 21:45:08,906::lvm::488::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
Thread-138::DEBUG::2013-03-20 21:45:08,906::lvm::490::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
Thread-138::DEBUG::2013-03-20 21:45:08,906::lvm::508::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-138::DEBUG::2013-03-20 21:45:08,907::lvm::510::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-138::DEBUG::2013-03-20 21:45:08,907::misc::1064::SamplingMethod::(__call__) Returning last result
Thread-138::DEBUG::2013-03-20 21:45:08,907::lvm::368::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
Thread-138::DEBUG::2013-03-20 21:45:08,908::misc::84::Storage.Misc.excCmd::(<lambda>) '/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 1083422e-a5db-41b6-b667-b9ef1ef244f0' (cwd None)
Thread-138::DEBUG::2013-03-20 21:45:08,927::misc::84::Storage.Misc.excCmd::(<lambda>) FAILED: <err> = '  Volume group "1083422e-a5db-41b6-b667-b9ef1ef244f0" not found\n'; <rc> = 5
Thread-138::WARNING::2013-03-20 21:45:08,928::lvm::373::Storage.LVM::(_reloadvgs) lvm vgs failed: 5 [] ['  Volume group "1083422e-a5db-41b6-b667-b9ef1ef244f0" not found']
Thread-138::DEBUG::2013-03-20 21:45:08,929::lvm::397::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
Thread-138::INFO::2013-03-20 21:45:08,987::nfsSD::68::Storage.StorageDomain::(create) sdUUID=1083422e-a5db-41b6-b667-b9ef1ef244f0 domainName=BO_data remotePath=bufferoverflow.home:/home/BO_Ovirt_Storage domClass=1
Thread-138::DEBUG::2013-03-20 21:45:09,063::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with FileMetadataRW backend
Thread-138::DEBUG::2013-03-20 21:45:09,064::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=[]
Thread-138::WARNING::2013-03-20 21:45:09,065::persistentDict::256::Storage.PersistentDict::(refresh) data has no embedded checksum - trust it as it is
Thread-138::DEBUG::2013-03-20 21:45:09,065::persistentDict::167::Storage.PersistentDict::(transaction) Starting transaction
Thread-138::DEBUG::2013-03-20 21:45:09,065::persistentDict::173::Storage.PersistentDict::(transaction) Flushing changes
Thread-138::DEBUG::2013-03-20 21:45:09,065::persistentDict::299::Storage.PersistentDict::(flush) about to write lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=BO_data', 'IOOPTIMEOUTSEC=1', 'LEASERETRIES=3', 'LEASETIMESEC=5', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'POOL_UUID=', 'REMOTE_PATH=bufferoverflow.home:/home/BO_Ovirt_Storage', 'ROLE=Regular', 'SDUUID=1083422e-a5db-41b6-b667-b9ef1ef244f0', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=8e5813bb1929fd4f7d9b6365ed8668d1d8f0b2af']
Thread-138::DEBUG::2013-03-20 21:45:09,069::persistentDict::175::Storage.PersistentDict::(transaction) Finished transaction
Thread-138::DEBUG::2013-03-20 21:45:09,070::fileSD::131::Storage.StorageDomain::(__init__) Reading domain in path /rhev/data-center/mnt/bufferoverflow.home:_home_BO__Ovirt__Storage/1083422e-a5db-41b6-b667-b9ef1ef244f0
Thread-138::DEBUG::2013-03-20 21:45:09,070::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with FileMetadataRW backend
Thread-138::DEBUG::2013-03-20 21:45:09,084::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=BO_data', 'IOOPTIMEOUTSEC=1', 'LEASERETRIES=3', 'LEASETIMESEC=5', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'POOL_UUID=', 'REMOTE_PATH=bufferoverflow.home:/home/BO_Ovirt_Storage', 'ROLE=Regular', 'SDUUID=1083422e-a5db-41b6-b667-b9ef1ef244f0', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=8e5813bb1929fd4f7d9b6365ed8668d1d8f0b2af']
Thread-138::DEBUG::2013-03-20 21:45:09,087::fileSD::503::Storage.StorageDomain::(imageGarbageCollector) Removing remnants of deleted images []
Thread-138::DEBUG::2013-03-20 21:45:09,087::resourceManager::395::ResourceManager::(registerNamespace) Registering namespace '1083422e-a5db-41b6-b667-b9ef1ef244f0_imageNS'
Thread-138::DEBUG::2013-03-20 21:45:09,087::resourceManager::395::ResourceManager::(registerNamespace) Registering namespace '1083422e-a5db-41b6-b667-b9ef1ef244f0_volumeNS'
Thread-138::DEBUG::2013-03-20 21:45:09,088::clusterlock::135::initSANLock::(initSANLock) Initializing SANLock for domain 1083422e-a5db-41b6-b667-b9ef1ef244f0
Thread-138::DEBUG::2013-03-20 21:45:09,101::sd::402::Storage.StorageDomain::(initSPMlease) lease initialized successfully
Thread-138::INFO::2013-03-20 21:45:09,102::logUtils::44::dispatcher::(wrapper) Run and protect: createStorageDomain, Return response: None
Thread-138::DEBUG::2013-03-20 21:45:09,102::task::1151::TaskManager.Task::(prepare) Task=`31a0ac28-1fbd-463e-afd6-fa6e64bb2f09`::finished: None
Thread-138::DEBUG::2013-03-20 21:45:09,102::task::568::TaskManager.Task::(_updateState) Task=`31a0ac28-1fbd-463e-afd6-fa6e64bb2f09`::moving from state preparing -> state finished
Thread-138::DEBUG::2013-03-20 21:45:09,102::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-138::DEBUG::2013-03-20 21:45:09,102::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-138::DEBUG::2013-03-20 21:45:09,103::task::957::TaskManager.Task::(_decref) Task=`31a0ac28-1fbd-463e-afd6-fa6e64bb2f09`::ref 0 aborting False
Thread-142::DEBUG::2013-03-20 21:45:09,112::BindingXMLRPC::161::vds::(wrapper) [10.100.101.108]
Thread-142::DEBUG::2013-03-20 21:45:09,113::task::568::TaskManager.Task::(_updateState) Task=`67a0f13c-b4fd-48fd-874b-4b2a843efffe`::moving from state init -> state preparing
Thread-142::INFO::2013-03-20 21:45:09,114::logUtils::41::dispatcher::(wrapper) Run and protect: getStorageDomainStats(sdUUID='1083422e-a5db-41b6-b667-b9ef1ef244f0', options=None)
Thread-142::DEBUG::2013-03-20 21:45:09,114::resourceManager::190::ResourceManager.Request::(__init__) ResName=`Storage.1083422e-a5db-41b6-b667-b9ef1ef244f0`ReqID=`42aca72d-9389-4c6c-89cc-9889b4038398`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '189' at '__init__'
Thread-142::DEBUG::2013-03-20 21:45:09,114::resourceManager::504::ResourceManager::(registerResource) Trying to register resource 'Storage.1083422e-a5db-41b6-b667-b9ef1ef244f0' for lock type 'shared'
Thread-142::DEBUG::2013-03-20 21:45:09,115::resourceManager::547::ResourceManager::(registerResource) Resource 'Storage.1083422e-a5db-41b6-b667-b9ef1ef244f0' is free. Now locking as 'shared' (1 active user)
Thread-142::DEBUG::2013-03-20 21:45:09,115::resourceManager::227::ResourceManager.Request::(grant) ResName=`Storage.1083422e-a5db-41b6-b667-b9ef1ef244f0`ReqID=`42aca72d-9389-4c6c-89cc-9889b4038398`::Granted request
Thread-142::DEBUG::2013-03-20 21:45:09,115::task::794::TaskManager.Task::(resourceAcquired) Task=`67a0f13c-b4fd-48fd-874b-4b2a843efffe`::_resourcesAcquired: Storage.1083422e-a5db-41b6-b667-b9ef1ef244f0 (shared)
Thread-142::DEBUG::2013-03-20 21:45:09,116::task::957::TaskManager.Task::(_decref) Task=`67a0f13c-b4fd-48fd-874b-4b2a843efffe`::ref 1 aborting False
Thread-142::INFO::2013-03-20 21:45:09,117::logUtils::44::dispatcher::(wrapper) Run and protect: getStorageDomainStats, Return response: {'stats': {'mdasize': 0, 'mdathreshold': True, 'mdavalid': True, 'diskfree': '387320905728', 'disktotal': '410991460352', 'mdafree': 0}}
Thread-142::DEBUG::2013-03-20 21:45:09,117::task::1151::TaskManager.Task::(prepare) Task=`67a0f13c-b4fd-48fd-874b-4b2a843efffe`::finished: {'stats': {'mdasize': 0, 'mdathreshold': True, 'mdavalid': True, 'diskfree': '387320905728', 'disktotal': '410991460352', 'mdafree': 0}}
Thread-142::DEBUG::2013-03-20 21:45:09,118::task::568::TaskManager.Task::(_updateState) Task=`67a0f13c-b4fd-48fd-874b-4b2a843efffe`::moving from state preparing -> state finished
Thread-142::DEBUG::2013-03-20 21:45:09,118::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.1083422e-a5db-41b6-b667-b9ef1ef244f0': < ResourceRef 'Storage.1083422e-a5db-41b6-b667-b9ef1ef244f0', isValid: 'True' obj: 'None'>}
Thread-142::DEBUG::2013-03-20 21:45:09,118::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-142::DEBUG::2013-03-20 21:45:09,118::resourceManager::557::ResourceManager::(releaseResource) Trying to release resource 'Storage.1083422e-a5db-41b6-b667-b9ef1ef244f0'
Thread-142::DEBUG::2013-03-20 21:45:09,119::resourceManager::573::ResourceManager::(releaseResource) Released resource 'Storage.1083422e-a5db-41b6-b667-b9ef1ef244f0' (0 active users)
Thread-142::DEBUG::2013-03-20 21:45:09,119::resourceManager::578::ResourceManager::(releaseResource) Resource 'Storage.1083422e-a5db-41b6-b667-b9ef1ef244f0' is free, finding out if anyone is waiting for it.
Thread-142::DEBUG::2013-03-20 21:45:09,119::resourceManager::585::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.1083422e-a5db-41b6-b667-b9ef1ef244f0', Clearing records.
Thread-142::DEBUG::2013-03-20 21:45:09,119::task::957::TaskManager.Task::(_decref) Task=`67a0f13c-b4fd-48fd-874b-4b2a843efffe`::ref 0 aborting False
Thread-143::DEBUG::2013-03-20 21:45:09,263::BindingXMLRPC::161::vds::(wrapper) [10.100.101.108]
Thread-143::DEBUG::2013-03-20 21:45:09,263::task::568::TaskManager.Task::(_updateState) Task=`397be2f4-7b83-4f29-ba82-9643ddfa53f3`::moving from state init -> state preparing
Thread-143::INFO::2013-03-20 21:45:09,264::logUtils::41::dispatcher::(wrapper) Run and protect: disconnectStorageServer(domType=1, spUUID='00000000-0000-0000-0000-000000000000', conList=[{'connection': 'bufferoverflow.home:/home/BO_Ovirt_Storage', 'iqn': '', 'portal': '', 'user': '', 'password': '******', 'id': '00000000-0000-0000-0000-000000000000', 'port': ''}], options=None)
Thread-143::DEBUG::2013-03-20 21:45:09,264::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/sudo -n /usr/bin/umount -f -l /rhev/data-center/mnt/bufferoverflow.home:_home_BO__Ovirt__Storage' (cwd None)
Thread-143::DEBUG::2013-03-20 21:45:09,297::misc::1054::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
Thread-143::DEBUG::2013-03-20 21:45:09,297::misc::1056::SamplingMethod::(__call__) Got in to sampling method
Thread-143::DEBUG::2013-03-20 21:45:09,297::misc::1054::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
Thread-143::DEBUG::2013-03-20 21:45:09,298::misc::1056::SamplingMethod::(__call__) Got in to sampling method
Thread-143::DEBUG::2013-03-20 21:45:09,298::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
Thread-143::DEBUG::2013-03-20 21:45:09,312::misc::84::Storage.Misc.excCmd::(<lambda>) FAILED: <err> = 'iscsiadm: No session found.\n'; <rc> = 21
Thread-143::DEBUG::2013-03-20 21:45:09,312::misc::1064::SamplingMethod::(__call__) Returning last result
MainProcess|Thread-143::DEBUG::2013-03-20 21:45:09,315::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/dd of=/sys/class/scsi_host/host0/scan' (cwd None)
MainProcess|Thread-143::DEBUG::2013-03-20 21:45:10,319::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/dd of=/sys/class/scsi_host/host1/scan' (cwd None)
MainProcess|Thread-143::DEBUG::2013-03-20 21:45:10,322::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/dd of=/sys/class/scsi_host/host2/scan' (cwd None)
MainProcess|Thread-143::DEBUG::2013-03-20 21:45:10,326::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/dd of=/sys/class/scsi_host/host3/scan' (cwd None)
MainProcess|Thread-143::DEBUG::2013-03-20 21:45:10,329::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/dd of=/sys/class/scsi_host/host4/scan' (cwd None)
MainProcess|Thread-143::DEBUG::2013-03-20 21:45:10,332::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/dd of=/sys/class/scsi_host/host5/scan' (cwd None)
MainProcess|Thread-143::DEBUG::2013-03-20 21:45:10,335::iscsi::402::Storage.ISCSI::(forceIScsiScan) Performing SCSI scan, this will take up to 30 seconds
Thread-145::DEBUG::2013-03-20 21:45:11,466::task::568::TaskManager.Task::(_updateState) Task=`bb7889a1-97d5-4f4f-98ff-e1ee56485adf`::moving from state init -> state preparing
Thread-145::INFO::2013-03-20 21:45:11,467::logUtils::41::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-145::INFO::2013-03-20 21:45:11,467::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-145::DEBUG::2013-03-20 21:45:11,467::task::1151::TaskManager.Task::(prepare) Task=`bb7889a1-97d5-4f4f-98ff-e1ee56485adf`::finished: {}
Thread-145::DEBUG::2013-03-20 21:45:11,467::task::568::TaskManager.Task::(_updateState) Task=`bb7889a1-97d5-4f4f-98ff-e1ee56485adf`::moving from state preparing -> state finished
Thread-145::DEBUG::2013-03-20 21:45:11,467::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-145::DEBUG::2013-03-20 21:45:11,468::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-145::DEBUG::2013-03-20 21:45:11,468::task::957::TaskManager.Task::(_decref) Task=`bb7889a1-97d5-4f4f-98ff-e1ee56485adf`::ref 0 aborting False
Thread-143::DEBUG::2013-03-20 21:45:12,337::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/sudo -n /sbin/multipath' (cwd None)
Thread-143::DEBUG::2013-03-20 21:45:12,362::misc::84::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> = ''; <rc> = 0
Thread-143::DEBUG::2013-03-20 21:45:12,362::lvm::477::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-143::DEBUG::2013-03-20 21:45:12,363::lvm::479::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-143::DEBUG::2013-03-20 21:45:12,363::lvm::488::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
Thread-143::DEBUG::2013-03-20 21:45:12,363::lvm::490::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
Thread-143::DEBUG::2013-03-20 21:45:12,363::lvm::508::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-143::DEBUG::2013-03-20 21:45:12,363::lvm::510::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-143::DEBUG::2013-03-20 21:45:12,363::misc::1064::SamplingMethod::(__call__) Returning last result
Thread-143::INFO::2013-03-20 21:45:12,363::logUtils::44::dispatcher::(wrapper) Run and protect: disconnectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': '00000000-0000-0000-0000-000000000000'}]}
Thread-143::DEBUG::2013-03-20 21:45:12,364::task::1151::TaskManager.Task::(prepare) Task=`397be2f4-7b83-4f29-ba82-9643ddfa53f3`::finished: {'statuslist': [{'status': 0, 'id': '00000000-0000-0000-0000-000000000000'}]}
Thread-143::DEBUG::2013-03-20 21:45:12,364::task::568::TaskManager.Task::(_updateState) Task=`397be2f4-7b83-4f29-ba82-9643ddfa53f3`::moving from state preparing -> state finished
Thread-143::DEBUG::2013-03-20 21:45:12,364::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-143::DEBUG::2013-03-20 21:45:12,364::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-143::DEBUG::2013-03-20 21:45:12,364::task::957::TaskManager.Task::(_decref) Task=`397be2f4-7b83-4f29-ba82-9643ddfa53f3`::ref 0 aborting False
Thread-147::DEBUG::2013-03-20 21:45:12,606::BindingXMLRPC::161::vds::(wrapper) [10.100.101.108]
Thread-147::DEBUG::2013-03-20 21:45:12,607::task::568::TaskManager.Task::(_updateState) Task=`e0ea3ead-907e-4f5f-85bb-8322da1af609`::moving from state init -> state preparing
Thread-147::INFO::2013-03-20 21:45:12,607::logUtils::41::dispatcher::(wrapper) Run and protect: validateStorageServerConnection(domType=1, spUUID='00000000-0000-0000-0000-000000000000', conList=[{'connection': 'bufferoverflow.home:/home/BO_Ovirt_Storage', 'iqn': '', 'portal': '', 'user': '', 'password': '******', 'id': '5ad206ce-b5a9-43b5-ac7d-acdae46a4a27', 'port': ''}], options=None)
Thread-147::INFO::2013-03-20 21:45:12,607::logUtils::44::dispatcher::(wrapper) Run and protect: validateStorageServerConnection, Return response: {'statuslist': [{'status': 0, 'id': '5ad206ce-b5a9-43b5-ac7d-acdae46a4a27'}]}
Thread-147::DEBUG::2013-03-20 21:45:12,607::task::1151::TaskManager.Task::(prepare) Task=`e0ea3ead-907e-4f5f-85bb-8322da1af609`::finished: {'statuslist': [{'status': 0, 'id': '5ad206ce-b5a9-43b5-ac7d-acdae46a4a27'}]}
Thread-147::DEBUG::2013-03-20 21:45:12,607::task::568::TaskManager.Task::(_updateState) Task=`e0ea3ead-907e-4f5f-85bb-8322da1af609`::moving from state preparing -> state finished
Thread-147::DEBUG::2013-03-20 21:45:12,607::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-147::DEBUG::2013-03-20 21:45:12,607::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-147::DEBUG::2013-03-20 21:45:12,607::task::957::TaskManager.Task::(_decref) Task=`e0ea3ead-907e-4f5f-85bb-8322da1af609`::ref 0 aborting False
Thread-148::DEBUG::2013-03-20 21:45:12,613::BindingXMLRPC::161::vds::(wrapper) [10.100.101.108]
Thread-148::DEBUG::2013-03-20 21:45:12,613::task::568::TaskManager.Task::(_updateState) Task=`20708494-013f-436e-8b05-2feaf91997b2`::moving from state init -> state preparing
Thread-148::INFO::2013-03-20 21:45:12,614::logUtils::41::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=1, spUUID='00000000-0000-0000-0000-000000000000', conList=[{'connection': 'bufferoverflow.home:/home/BO_Ovirt_Storage', 'iqn': '', 'portal': '', 'user': '', 'password': '******', 'id': '5ad206ce-b5a9-43b5-ac7d-acdae46a4a27', 'port': ''}], options=None)
Thread-148::DEBUG::2013-03-20 21:45:12,617::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/sudo -n /usr/bin/mount -t nfs -o soft,nosharecache,timeo=600,retrans=6,nfsvers=3 bufferoverflow.home:/home/BO_Ovirt_Storage /rhev/data-center/mnt/bufferoverflow.home:_home_BO__Ovirt__Storage' (cwd None)
Thread-148::INFO::2013-03-20 21:45:12,675::logUtils::44::dispatcher::(wrapper) Run and protect: connectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': '5ad206ce-b5a9-43b5-ac7d-acdae46a4a27'}]}
Thread-148::DEBUG::2013-03-20 21:45:12,675::task::1151::TaskManager.Task::(prepare) Task=`20708494-013f-436e-8b05-2feaf91997b2`::finished: {'statuslist': [{'status': 0, 'id': '5ad206ce-b5a9-43b5-ac7d-acdae46a4a27'}]}
Thread-148::DEBUG::2013-03-20 21:45:12,675::task::568::TaskManager.Task::(_updateState) Task=`20708494-013f-436e-8b05-2feaf91997b2`::moving from state preparing -> state finished
Thread-148::DEBUG::2013-03-20 21:45:12,676::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-148::DEBUG::2013-03-20 21:45:12,676::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-148::DEBUG::2013-03-20 21:45:12,676::task::957::TaskManager.Task::(_decref) Task=`20708494-013f-436e-8b05-2feaf91997b2`::ref 0 aborting False
Thread-149::DEBUG::2013-03-20 21:45:12,690::BindingXMLRPC::161::vds::(wrapper) [10.100.101.108]
Thread-149::DEBUG::2013-03-20 21:45:12,690::task::568::TaskManager.Task::(_updateState) Task=`052ee545-9efb-409b-975e-9284986528ce`::moving from state init -> state preparing
Thread-149::INFO::2013-03-20 21:45:12,691::logUtils::41::dispatcher::(wrapper) Run and protect: createStoragePool(poolType=None, spUUID='5849b030-626e-47cb-ad90-3ce782d831b3', poolName='Default', masterDom='1083422e-a5db-41b6-b667-b9ef1ef244f0', domList=['1083422e-a5db-41b6-b667-b9ef1ef244f0'], masterVersion=15, lockPolicy=None, lockRenewalIntervalSec=5, leaseTimeSec=60, ioOpTimeoutSec=10, leaseRetries=3, options=None)
Thread-149::INFO::2013-03-20 21:45:12,691::fileSD::302::Storage.StorageDomain::(validate) sdUUID=1083422e-a5db-41b6-b667-b9ef1ef244f0
Thread-149::DEBUG::2013-03-20 21:45:12,706::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=BO_data', 'IOOPTIMEOUTSEC=1', 'LEASERETRIES=3', 'LEASETIMESEC=5', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'POOL_UUID=', 'REMOTE_PATH=bufferoverflow.home:/home/BO_Ovirt_Storage', 'ROLE=Regular', 'SDUUID=1083422e-a5db-41b6-b667-b9ef1ef244f0', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=8e5813bb1929fd4f7d9b6365ed8668d1d8f0b2af']
Thread-149::DEBUG::2013-03-20 21:45:12,707::resourceManager::190::ResourceManager.Request::(__init__) ResName=`Storage.5849b030-626e-47cb-ad90-3ce782d831b3`ReqID=`5aca65b6-4fd9-4952-9ffb-c9487242eb89`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '189' at '__init__'
Thread-149::DEBUG::2013-03-20 21:45:12,707::resourceManager::504::ResourceManager::(registerResource) Trying to register resource 'Storage.5849b030-626e-47cb-ad90-3ce782d831b3' for lock type 'exclusive'
Thread-149::DEBUG::2013-03-20 21:45:12,707::resourceManager::547::ResourceManager::(registerResource) Resource 'Storage.5849b030-626e-47cb-ad90-3ce782d831b3' is free. Now locking as 'exclusive' (1 active user)
Thread-149::DEBUG::2013-03-20 21:45:12,707::resourceManager::227::ResourceManager.Request::(grant) ResName=`Storage.5849b030-626e-47cb-ad90-3ce782d831b3`ReqID=`5aca65b6-4fd9-4952-9ffb-c9487242eb89`::Granted request
Thread-149::DEBUG::2013-03-20 21:45:12,708::task::794::TaskManager.Task::(resourceAcquired) Task=`052ee545-9efb-409b-975e-9284986528ce`::_resourcesAcquired: Storage.5849b030-626e-47cb-ad90-3ce782d831b3 (exclusive)
Thread-149::DEBUG::2013-03-20 21:45:12,708::task::957::TaskManager.Task::(_decref) Task=`052ee545-9efb-409b-975e-9284986528ce`::ref 1 aborting False
Thread-149::DEBUG::2013-03-20 21:45:12,709::resourceManager::190::ResourceManager.Request::(__init__) ResName=`Storage.1083422e-a5db-41b6-b667-b9ef1ef244f0`ReqID=`9679bd25-4fd7-4515-8598-6c2526660c0e`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '189' at '__init__'
Thread-149::DEBUG::2013-03-20 21:45:12,709::resourceManager::504::ResourceManager::(registerResource) Trying to register resource 'Storage.1083422e-a5db-41b6-b667-b9ef1ef244f0' for lock type 'exclusive'
Thread-149::DEBUG::2013-03-20 21:45:12,709::resourceManager::547::ResourceManager::(registerResource) Resource 'Storage.1083422e-a5db-41b6-b667-b9ef1ef244f0' is free. Now locking as 'exclusive' (1 active user)
Thread-149::DEBUG::2013-03-20 21:45:12,709::resourceManager::227::ResourceManager.Request::(grant) ResName=`Storage.1083422e-a5db-41b6-b667-b9ef1ef244f0`ReqID=`9679bd25-4fd7-4515-8598-6c2526660c0e`::Granted request
Thread-149::DEBUG::2013-03-20 21:45:12,710::task::794::TaskManager.Task::(resourceAcquired) Task=`052ee545-9efb-409b-975e-9284986528ce`::_resourcesAcquired: Storage.1083422e-a5db-41b6-b667-b9ef1ef244f0 (exclusive)
Thread-149::DEBUG::2013-03-20 21:45:12,710::task::957::TaskManager.Task::(_decref) Task=`052ee545-9efb-409b-975e-9284986528ce`::ref 1 aborting False
Thread-149::INFO::2013-03-20 21:45:12,710::sp::542::Storage.StoragePool::(create) spUUID=5849b030-626e-47cb-ad90-3ce782d831b3 poolName=Default master_sd=1083422e-a5db-41b6-b667-b9ef1ef244f0 domList=['1083422e-a5db-41b6-b667-b9ef1ef244f0'] masterVersion=15 {'LEASETIMESEC': 60, 'IOOPTIMEOUTSEC': 10, 'LEASERETRIES': 3, 'LOCKRENEWALINTERVALSEC': 5}
Thread-149::INFO::2013-03-20 21:45:12,710::fileSD::302::Storage.StorageDomain::(validate) sdUUID=1083422e-a5db-41b6-b667-b9ef1ef244f0
Thread-149::DEBUG::2013-03-20 21:45:12,724::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=BO_data', 'IOOPTIMEOUTSEC=1', 'LEASERETRIES=3', 'LEASETIMESEC=5', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'POOL_UUID=', 'REMOTE_PATH=bufferoverflow.home:/home/BO_Ovirt_Storage', 'ROLE=Regular', 'SDUUID=1083422e-a5db-41b6-b667-b9ef1ef244f0', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=8e5813bb1929fd4f7d9b6365ed8668d1d8f0b2af']
Thread-149::DEBUG::2013-03-20 21:45:12,737::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=BO_data', 'IOOPTIMEOUTSEC=1', 'LEASERETRIES=3', 'LEASETIMESEC=5', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'POOL_UUID=', 'REMOTE_PATH=bufferoverflow.home:/home/BO_Ovirt_Storage', 'ROLE=Regular', 'SDUUID=1083422e-a5db-41b6-b667-b9ef1ef244f0', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=8e5813bb1929fd4f7d9b6365ed8668d1d8f0b2af']
Thread-149::DEBUG::2013-03-20 21:45:12,738::persistentDict::167::Storage.PersistentDict::(transaction) Starting transaction
Thread-149::DEBUG::2013-03-20 21:45:12,738::persistentDict::173::Storage.PersistentDict::(transaction) Flushing changes
Thread-149::DEBUG::2013-03-20 21:45:12,739::persistentDict::299::Storage.PersistentDict::(flush) about to write lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=BO_data', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'POOL_UUID=', 'REMOTE_PATH=bufferoverflow.home:/home/BO_Ovirt_Storage', 'ROLE=Regular', 'SDUUID=1083422e-a5db-41b6-b667-b9ef1ef244f0', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=8e2e4f617c49fda319e0b7fb8ed36a065e0e4c79']
Thread-149::DEBUG::2013-03-20 21:45:12,742::persistentDict::175::Storage.PersistentDict::(transaction) Finished transaction
Thread-149::INFO::2013-03-20 21:45:12,743::clusterlock::172::SANLock::(acquireHostId) Acquiring host id for domain 1083422e-a5db-41b6-b667-b9ef1ef244f0 (id: 250)
Thread-154::DEBUG::2013-03-20 21:45:21,525::task::568::TaskManager.Task::(_updateState) Task=`9a9fb5a4-c0b1-49ab-85bc-77d6a975331e`::moving from state init -> state preparing
Thread-154::INFO::2013-03-20 21:45:21,526::logUtils::41::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-154::INFO::2013-03-20 21:45:21,526::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-154::DEBUG::2013-03-20 21:45:21,526::task::1151::TaskManager.Task::(prepare) Task=`9a9fb5a4-c0b1-49ab-85bc-77d6a975331e`::finished: {}
Thread-154::DEBUG::2013-03-20 21:45:21,526::task::568::TaskManager.Task::(_updateState) Task=`9a9fb5a4-c0b1-49ab-85bc-77d6a975331e`::moving from state preparing -> state finished
Thread-154::DEBUG::2013-03-20 21:45:21,527::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-154::DEBUG::2013-03-20 21:45:21,527::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-154::DEBUG::2013-03-20 21:45:21,527::task::957::TaskManager.Task::(_decref) Task=`9a9fb5a4-c0b1-49ab-85bc-77d6a975331e`::ref 0 aborting False
Thread-160::DEBUG::2013-03-20 21:45:31,642::task::568::TaskManager.Task::(_updateState) Task=`b682ec91-4bea-4d01-87f7-f8da0e29404e`::moving from state init -> state preparing
Thread-160::INFO::2013-03-20 21:45:31,643::logUtils::41::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-160::INFO::2013-03-20 21:45:31,643::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-160::DEBUG::2013-03-20 21:45:31,643::task::1151::TaskManager.Task::(prepare) Task=`b682ec91-4bea-4d01-87f7-f8da0e29404e`::finished: {}
Thread-160::DEBUG::2013-03-20 21:45:31,643::task::568::TaskManager.Task::(_updateState) Task=`b682ec91-4bea-4d01-87f7-f8da0e29404e`::moving from state preparing -> state finished
Thread-160::DEBUG::2013-03-20 21:45:31,643::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-160::DEBUG::2013-03-20 21:45:31,644::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-160::DEBUG::2013-03-20 21:45:31,644::task::957::TaskManager.Task::(_decref) Task=`b682ec91-4bea-4d01-87f7-f8da0e29404e`::ref 0 aborting False
Thread-149::ERROR::2013-03-20 21:45:33,745::task::833::TaskManager.Task::(_setError) Task=`052ee545-9efb-409b-975e-9284986528ce`::Unexpected error
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/task.py", line 840, in _run
    return fn(*args, **kargs)
  File "/usr/share/vdsm/logUtils.py", line 42, in wrapper
    res = f(*args, **kwargs)
  File "/usr/share/vdsm/storage/hsm.py", line 895, in createStoragePool
    masterVersion, leaseParams)
  File "/usr/share/vdsm/storage/sp.py", line 567, in create
    self._acquireTemporaryClusterLock(msdUUID, leaseParams)
  File "/usr/share/vdsm/storage/sp.py", line 509, in _acquireTemporaryClusterLock
    msd.acquireHostId(self.id)
  File "/usr/share/vdsm/storage/sd.py", line 436, in acquireHostId
    self._clusterLock.acquireHostId(hostId, async)
  File "/usr/share/vdsm/storage/clusterlock.py", line 187, in acquireHostId
    raise se.AcquireHostIdFailure(self._sdUUID, e)
AcquireHostIdFailure: Cannot acquire host id: ('1083422e-a5db-41b6-b667-b9ef1ef244f0', SanlockException(-203, 'Sanlock lockspace add failure', 'Sanlock exception'))
Thread-149::DEBUG::2013-03-20 21:45:33,748::task::852::TaskManager.Task::(_run) Task=`052ee545-9efb-409b-975e-9284986528ce`::Task._run: 052ee545-9efb-409b-975e-9284986528ce (None, '5849b030-626e-47cb-ad90-3ce782d831b3', 'Default', '1083422e-a5db-41b6-b667-b9ef1ef244f0', ['1083422e-a5db-41b6-b667-b9ef1ef244f0'], 15, None, 5, 60, 10, 3) {} failed - stopping task
Thread-149::DEBUG::2013-03-20 21:45:33,748::task::1177::TaskManager.Task::(stop) Task=`052ee545-9efb-409b-975e-9284986528ce`::stopping in state preparing (force False)
Thread-149::DEBUG::2013-03-20 21:45:33,748::task::957::TaskManager.Task::(_decref) Task=`052ee545-9efb-409b-975e-9284986528ce`::ref 1 aborting True
Thread-149::INFO::2013-03-20 21:45:33,748::task::1134::TaskManager.Task::(prepare) Task=`052ee545-9efb-409b-975e-9284986528ce`::aborting: Task is aborted: 'Cannot acquire host id' - code 661
Thread-149::DEBUG::2013-03-20 21:45:33,748::task::1139::TaskManager.Task::(prepare) Task=`052ee545-9efb-409b-975e-9284986528ce`::Prepare: aborted: Cannot acquire host id
Thread-149::DEBUG::2013-03-20 21:45:33,749::task::957::TaskManager.Task::(_decref) Task=`052ee545-9efb-409b-975e-9284986528ce`::ref 0 aborting True
Thread-149::DEBUG::2013-03-20 21:45:33,749::task::892::TaskManager.Task::(_doAbort) Task=`052ee545-9efb-409b-975e-9284986528ce`::Task._doAbort: force False
Thread-149::DEBUG::2013-03-20 21:45:33,749::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-149::DEBUG::2013-03-20 21:45:33,749::task::568::TaskManager.Task::(_updateState) Task=`052ee545-9efb-409b-975e-9284986528ce`::moving from state preparing -> state aborting
Thread-149::DEBUG::2013-03-20 21:45:33,749::task::523::TaskManager.Task::(__state_aborting) Task=`052ee545-9efb-409b-975e-9284986528ce`::_aborting: recover policy none
Thread-149::DEBUG::2013-03-20 21:45:33,749::task::568::TaskManager.Task::(_updateState) Task=`052ee545-9efb-409b-975e-9284986528ce`::moving from state aborting -> state failed
Thread-149::DEBUG::2013-03-20 21:45:33,749::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.5849b030-626e-47cb-ad90-3ce782d831b3': < ResourceRef 'Storage.5849b030-626e-47cb-ad90-3ce782d831b3', isValid: 'True' obj: 'None'>, 'Storage.1083422e-a5db-41b6-b667-b9ef1ef244f0': < ResourceRef 'Storage.1083422e-a5db-41b6-b667-b9ef1ef244f0', isValid: 'True' obj: 'None'>}
Thread-149::DEBUG::2013-03-20 21:45:33,750::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-149::DEBUG::2013-03-20 21:45:33,750::resourceManager::557::ResourceManager::(releaseResource) Trying to release resource 'Storage.5849b030-626e-47cb-ad90-3ce782d831b3'
Thread-149::DEBUG::2013-03-20 21:45:33,750::resourceManager::573::ResourceManager::(releaseResource) Released resource 'Storage.5849b030-626e-47cb-ad90-3ce782d831b3' (0 active users)
Thread-149::DEBUG::2013-03-20 21:45:33,750::resourceManager::578::ResourceManager::(releaseResource) Resource 'Storage.5849b030-626e-47cb-ad90-3ce782d831b3' is free, finding out if anyone is waiting for it.
Thread-149::DEBUG::2013-03-20 21:45:33,750::resourceManager::585::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.5849b030-626e-47cb-ad90-3ce782d831b3', Clearing records.
Thread-149::DEBUG::2013-03-20 21:45:33,750::resourceManager::557::ResourceManager::(releaseResource) Trying to release resource 'Storage.1083422e-a5db-41b6-b667-b9ef1ef244f0'
Thread-149::DEBUG::2013-03-20 21:45:33,750::resourceManager::573::ResourceManager::(releaseResource) Released resource 'Storage.1083422e-a5db-41b6-b667-b9ef1ef244f0' (0 active users)
Thread-149::DEBUG::2013-03-20 21:45:33,750::resourceManager::578::ResourceManager::(releaseResource) Resource 'Storage.1083422e-a5db-41b6-b667-b9ef1ef244f0' is free, finding out if anyone is waiting for it.
Thread-149::DEBUG::2013-03-20 21:45:33,750::resourceManager::585::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.1083422e-a5db-41b6-b667-b9ef1ef244f0', Clearing records.
Thread-149::ERROR::2013-03-20 21:45:33,751::dispatcher::67::Storage.Dispatcher.Protect::(run) {'status': {'message': "Cannot acquire host id: ('1083422e-a5db-41b6-b667-b9ef1ef244f0', SanlockException(-203, 'Sanlock lockspace add failure', 'Sanlock exception'))", 'code': 661}}
Thread-166::DEBUG::2013-03-20 21:45:41,703::task::568::TaskManager.Task::(_updateState) Task=`a43df96f-b2ef-42fe-b1a3-a05b04cae904`::moving from state init -> state preparing
Thread-166::INFO::2013-03-20 21:45:41,703::logUtils::41::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-166::INFO::2013-03-20 21:45:41,703::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-166::DEBUG::2013-03-20 21:45:41,704::task::1151::TaskManager.Task::(prepare) Task=`a43df96f-b2ef-42fe-b1a3-a05b04cae904`::finished: {}
Thread-166::DEBUG::2013-03-20 21:45:41,704::task::568::TaskManager.Task::(_updateState) Task=`a43df96f-b2ef-42fe-b1a3-a05b04cae904`::moving from state preparing -> state finished
Thread-166::DEBUG::2013-03-20 21:45:41,704::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-166::DEBUG::2013-03-20 21:45:41,704::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-166::DEBUG::2013-03-20 21:45:41,704::task::957::TaskManager.Task::(_decref) Task=`a43df96f-b2ef-42fe-b1a3-a05b04cae904`::ref 0 aborting False
Thread-172::DEBUG::2013-03-20 21:45:51,762::task::568::TaskManager.Task::(_updateState) Task=`203f5c96-36b1-46ba-8509-b9d4ec0799e0`::moving from state init -> state preparing
Thread-172::INFO::2013-03-20 21:45:51,762::logUtils::41::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-172::INFO::2013-03-20 21:45:51,762::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-172::DEBUG::2013-03-20 21:45:51,763::task::1151::TaskManager.Task::(prepare) Task=`203f5c96-36b1-46ba-8509-b9d4ec0799e0`::finished: {}
Thread-172::DEBUG::2013-03-20 21:45:51,763::task::568::TaskManager.Task::(_updateState) Task=`203f5c96-36b1-46ba-8509-b9d4ec0799e0`::moving from state preparing -> state finished
Thread-172::DEBUG::2013-03-20 21:45:51,763::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-172::DEBUG::2013-03-20 21:45:51,763::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-172::DEBUG::2013-03-20 21:45:51,763::task::957::TaskManager.Task::(_decref) Task=`203f5c96-36b1-46ba-8509-b9d4ec0799e0`::ref 0 aborting False
Thread-178::DEBUG::2013-03-20 21:46:01,823::task::568::TaskManager.Task::(_updateState) Task=`e250afb9-d6e6-42f1-8805-3697124a8c23`::moving from state init -> state preparing
Thread-178::INFO::2013-03-20 21:46:01,823::logUtils::41::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-178::INFO::2013-03-20 21:46:01,824::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-178::DEBUG::2013-03-20 21:46:01,824::task::1151::TaskManager.Task::(prepare) Task=`e250afb9-d6e6-42f1-8805-3697124a8c23`::finished: {}
Thread-178::DEBUG::2013-03-20 21:46:01,824::task::568::TaskManager.Task::(_updateState) Task=`e250afb9-d6e6-42f1-8805-3697124a8c23`::moving from state preparing -> state finished
Thread-178::DEBUG::2013-03-20 21:46:01,824::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-178::DEBUG::2013-03-20 21:46:01,824::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-178::DEBUG::2013-03-20 21:46:01,824::task::957::TaskManager.Task::(_decref) Task=`e250afb9-d6e6-42f1-8805-3697124a8c23`::ref 0 aborting False
Thread-180::DEBUG::2013-03-20 21:46:01,850::BindingXMLRPC::161::vds::(wrapper) [10.100.101.108]
Thread-180::DEBUG::2013-03-20 21:46:01,850::task::568::TaskManager.Task::(_updateState) Task=`f1c530e2-904f-4143-bd30-c0bffd03541f`::moving from state init -> state preparing
Thread-180::INFO::2013-03-20 21:46:01,851::logUtils::41::dispatcher::(wrapper) Run and protect: validateStorageServerConnection(domType=1, spUUID='00000000-0000-0000-0000-000000000000', conList=[{'connection': 'bufferoverflow.home:/home/BO_Ovirt_Storage', 'iqn': '', 'portal': '', 'user': '', 'password': '******', 'id': '5ad206ce-b5a9-43b5-ac7d-acdae46a4a27', 'port': ''}], options=None)
Thread-180::INFO::2013-03-20 21:46:01,851::logUtils::44::dispatcher::(wrapper) Run and protect: validateStorageServerConnection, Return response: {'statuslist': [{'status': 0, 'id': '5ad206ce-b5a9-43b5-ac7d-acdae46a4a27'}]}
Thread-180::DEBUG::2013-03-20 21:46:01,851::task::1151::TaskManager.Task::(prepare) Task=`f1c530e2-904f-4143-bd30-c0bffd03541f`::finished: {'statuslist': [{'status': 0, 'id': '5ad206ce-b5a9-43b5-ac7d-acdae46a4a27'}]}
Thread-180::DEBUG::2013-03-20 21:46:01,851::task::568::TaskManager.Task::(_updateState) Task=`f1c530e2-904f-4143-bd30-c0bffd03541f`::moving from state preparing -> state finished
Thread-180::DEBUG::2013-03-20 21:46:01,851::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-180::DEBUG::2013-03-20 21:46:01,851::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-180::DEBUG::2013-03-20 21:46:01,851::task::957::TaskManager.Task::(_decref) Task=`f1c530e2-904f-4143-bd30-c0bffd03541f`::ref 0 aborting False
Thread-181::DEBUG::2013-03-20 21:46:01,860::BindingXMLRPC::161::vds::(wrapper) [10.100.101.108]
Thread-181::DEBUG::2013-03-20 21:46:01,861::task::568::TaskManager.Task::(_updateState) Task=`b516db87-b192-464a-916b-363258c95a8e`::moving from state init -> state preparing
Thread-181::INFO::2013-03-20 21:46:01,861::logUtils::41::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=1, spUUID='00000000-0000-0000-0000-000000000000', conList=[{'connection': 'bufferoverflow.home:/home/BO_Ovirt_Storage', 'iqn': '', 'portal': '', 'user': '', 'password': '******', 'id': '5ad206ce-b5a9-43b5-ac7d-acdae46a4a27', 'port': ''}], options=None)
Thread-181::INFO::2013-03-20 21:46:01,867::logUtils::44::dispatcher::(wrapper) Run and protect: connectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': '5ad206ce-b5a9-43b5-ac7d-acdae46a4a27'}]}
Thread-181::DEBUG::2013-03-20 21:46:01,867::task::1151::TaskManager.Task::(prepare) Task=`b516db87-b192-464a-916b-363258c95a8e`::finished: {'statuslist': [{'status': 0, 'id': '5ad206ce-b5a9-43b5-ac7d-acdae46a4a27'}]}
Thread-181::DEBUG::2013-03-20 21:46:01,867::task::568::TaskManager.Task::(_updateState) Task=`b516db87-b192-464a-916b-363258c95a8e`::moving from state preparing -> state finished
Thread-181::DEBUG::2013-03-20 21:46:01,867::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-181::DEBUG::2013-03-20 21:46:01,867::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-181::DEBUG::2013-03-20 21:46:01,867::task::957::TaskManager.Task::(_decref) Task=`b516db87-b192-464a-916b-363258c95a8e`::ref 0 aborting False
Thread-182::DEBUG::2013-03-20 21:46:01,877::BindingXMLRPC::161::vds::(wrapper) [10.100.101.108]
Thread-182::DEBUG::2013-03-20 21:46:01,877::task::568::TaskManager.Task::(_updateState) Task=`e494d4ca-3f39-4bf0-aa23-0c69abf1c03c`::moving from state init -> state preparing
Thread-182::INFO::2013-03-20 21:46:01,878::logUtils::41::dispatcher::(wrapper) Run and protect: createStoragePool(poolType=None, spUUID='5849b030-626e-47cb-ad90-3ce782d831b3', poolName='Default', masterDom='1083422e-a5db-41b6-b667-b9ef1ef244f0', domList=['1083422e-a5db-41b6-b667-b9ef1ef244f0'], masterVersion=16, lockPolicy=None, lockRenewalIntervalSec=5, leaseTimeSec=60, ioOpTimeoutSec=10, leaseRetries=3, options=None)
Thread-182::INFO::2013-03-20 21:46:01,878::fileSD::302::Storage.StorageDomain::(validate) sdUUID=1083422e-a5db-41b6-b667-b9ef1ef244f0
Thread-182::DEBUG::2013-03-20 21:46:01,891::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=BO_data', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'POOL_UUID=', 'REMOTE_PATH=bufferoverflow.home:/home/BO_Ovirt_Storage', 'ROLE=Regular', 'SDUUID=1083422e-a5db-41b6-b667-b9ef1ef244f0', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=8e2e4f617c49fda319e0b7fb8ed36a065e0e4c79']
Thread-182::DEBUG::2013-03-20 21:46:01,891::resourceManager::190::ResourceManager.Request::(__init__) ResName=`Storage.5849b030-626e-47cb-ad90-3ce782d831b3`ReqID=`bb78f788-a14f-4650-9c25-29b0738c3454`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '189' at '__init__'
Thread-182::DEBUG::2013-03-20 21:46:01,891::resourceManager::504::ResourceManager::(registerResource) Trying to register resource 'Storage.5849b030-626e-47cb-ad90-3ce782d831b3' for lock type 'exclusive'
Thread-182::DEBUG::2013-03-20 21:46:01,891::resourceManager::547::ResourceManager::(registerResource) Resource 'Storage.5849b030-626e-47cb-ad90-3ce782d831b3' is free. Now locking as 'exclusive' (1 active user)
Thread-182::DEBUG::2013-03-20 21:46:01,891::resourceManager::227::ResourceManager.Request::(grant) ResName=`Storage.5849b030-626e-47cb-ad90-3ce782d831b3`ReqID=`bb78f788-a14f-4650-9c25-29b0738c3454`::Granted request
Thread-182::DEBUG::2013-03-20 21:46:01,893::task::794::TaskManager.Task::(resourceAcquired) Task=`e494d4ca-3f39-4bf0-aa23-0c69abf1c03c`::_resourcesAcquired: Storage.5849b030-626e-47cb-ad90-3ce782d831b3 (exclusive)
Thread-182::DEBUG::2013-03-20 21:46:01,893::task::957::TaskManager.Task::(_decref) Task=`e494d4ca-3f39-4bf0-aa23-0c69abf1c03c`::ref 1 aborting False
Thread-182::DEBUG::2013-03-20 21:46:01,893::resourceManager::190::ResourceManager.Request::(__init__) ResName=`Storage.1083422e-a5db-41b6-b667-b9ef1ef244f0`ReqID=`ec1efa04-3417-4bb0-9171-2c8c3f628807`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '189' at '__init__'
Thread-182::DEBUG::2013-03-20 21:46:01,893::resourceManager::504::ResourceManager::(registerResource) Trying to register resource 'Storage.1083422e-a5db-41b6-b667-b9ef1ef244f0' for lock type 'exclusive'
Thread-182::DEBUG::2013-03-20 21:46:01,893::resourceManager::547::ResourceManager::(registerResource) Resource 'Storage.1083422e-a5db-41b6-b667-b9ef1ef244f0' is free. Now locking as 'exclusive' (1 active user)
Thread-182::DEBUG::2013-03-20 21:46:01,893::resourceManager::227::ResourceManager.Request::(grant) ResName=`Storage.1083422e-a5db-41b6-b667-b9ef1ef244f0`ReqID=`ec1efa04-3417-4bb0-9171-2c8c3f628807`::Granted request
Thread-182::DEBUG::2013-03-20 21:46:01,893::task::794::TaskManager.Task::(resourceAcquired) Task=`e494d4ca-3f39-4bf0-aa23-0c69abf1c03c`::_resourcesAcquired: Storage.1083422e-a5db-41b6-b667-b9ef1ef244f0 (exclusive)
Thread-182::DEBUG::2013-03-20 21:46:01,893::task::957::TaskManager.Task::(_decref) Task=`e494d4ca-3f39-4bf0-aa23-0c69abf1c03c`::ref 1 aborting False
Thread-182::INFO::2013-03-20 21:46:01,894::sp::542::Storage.StoragePool::(create) spUUID=5849b030-626e-47cb-ad90-3ce782d831b3 poolName=Default master_sd=1083422e-a5db-41b6-b667-b9ef1ef244f0 domList=['1083422e-a5db-41b6-b667-b9ef1ef244f0'] masterVersion=16 {'LEASETIMESEC': 60, 'IOOPTIMEOUTSEC': 10, 'LEASERETRIES': 3, 'LOCKRENEWALINTERVALSEC': 5}
Thread-182::INFO::2013-03-20 21:46:01,894::fileSD::302::Storage.StorageDomain::(validate) sdUUID=1083422e-a5db-41b6-b667-b9ef1ef244f0
Thread-182::DEBUG::2013-03-20 21:46:01,900::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=BO_data', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'POOL_UUID=', 'REMOTE_PATH=bufferoverflow.home:/home/BO_Ovirt_Storage', 'ROLE=Regular', 'SDUUID=1083422e-a5db-41b6-b667-b9ef1ef244f0', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=8e2e4f617c49fda319e0b7fb8ed36a065e0e4c79']
Thread-182::DEBUG::2013-03-20 21:46:01,907::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=BO_data', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'POOL_UUID=', 'REMOTE_PATH=bufferoverflow.home:/home/BO_Ovirt_Storage', 'ROLE=Regular', 'SDUUID=1083422e-a5db-41b6-b667-b9ef1ef244f0', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=8e2e4f617c49fda319e0b7fb8ed36a065e0e4c79']
Thread-182::WARNING::2013-03-20 21:46:01,907::fileUtils::185::fileUtils::(createdir) Dir /rhev/data-center/5849b030-626e-47cb-ad90-3ce782d831b3 already exists
Thread-182::DEBUG::2013-03-20 21:46:01,907::persistentDict::167::Storage.PersistentDict::(transaction) Starting transaction
Thread-182::DEBUG::2013-03-20 21:46:01,907::persistentDict::175::Storage.PersistentDict::(transaction) Finished transaction
Thread-182::INFO::2013-03-20 21:46:01,907::clusterlock::172::SANLock::(acquireHostId) Acquiring host id for domain 1083422e-a5db-41b6-b667-b9ef1ef244f0 (id: 250)
Thread-187::DEBUG::2013-03-20 21:46:11,882::task::568::TaskManager.Task::(_updateState) Task=`8f81d4b2-7fec-4caf-9dad-1ecd542f5e7d`::moving from state init -> state preparing
Thread-187::INFO::2013-03-20 21:46:11,882::logUtils::41::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-187::INFO::2013-03-20 21:46:11,883::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-187::DEBUG::2013-03-20 21:46:11,883::task::1151::TaskManager.Task::(prepare) Task=`8f81d4b2-7fec-4caf-9dad-1ecd542f5e7d`::finished: {}
Thread-187::DEBUG::2013-03-20 21:46:11,883::task::568::TaskManager.Task::(_updateState) Task=`8f81d4b2-7fec-4caf-9dad-1ecd542f5e7d`::moving from state preparing -> state finished
Thread-187::DEBUG::2013-03-20 21:46:11,883::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-187::DEBUG::2013-03-20 21:46:11,883::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-187::DEBUG::2013-03-20 21:46:11,883::task::957::TaskManager.Task::(_decref) Task=`8f81d4b2-7fec-4caf-9dad-1ecd542f5e7d`::ref 0 aborting False
Thread-193::DEBUG::2013-03-20 21:46:21,942::task::568::TaskManager.Task::(_updateState) Task=`43ec72d6-562c-41d6-aeec-8573ef113c47`::moving from state init -> state preparing
Thread-193::INFO::2013-03-20 21:46:21,943::logUtils::41::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-193::INFO::2013-03-20 21:46:21,943::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-193::DEBUG::2013-03-20 21:46:21,943::task::1151::TaskManager.Task::(prepare) Task=`43ec72d6-562c-41d6-aeec-8573ef113c47`::finished: {}
Thread-193::DEBUG::2013-03-20 21:46:21,943::task::568::TaskManager.Task::(_updateState) Task=`43ec72d6-562c-41d6-aeec-8573ef113c47`::moving from state preparing -> state finished
Thread-193::DEBUG::2013-03-20 21:46:21,944::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-193::DEBUG::2013-03-20 21:46:21,944::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-193::DEBUG::2013-03-20 21:46:21,944::task::957::TaskManager.Task::(_decref) Task=`43ec72d6-562c-41d6-aeec-8573ef113c47`::ref 0 aborting False
Thread-182::ERROR::2013-03-20 21:46:22,910::task::833::TaskManager.Task::(_setError) Task=`e494d4ca-3f39-4bf0-aa23-0c69abf1c03c`::Unexpected error
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/task.py", line 840, in _run
    return fn(*args, **kargs)
  File "/usr/share/vdsm/logUtils.py", line 42, in wrapper
    res = f(*args, **kwargs)
  File "/usr/share/vdsm/storage/hsm.py", line 895, in createStoragePool
    masterVersion, leaseParams)
  File "/usr/share/vdsm/storage/sp.py", line 567, in create
    self._acquireTemporaryClusterLock(msdUUID, leaseParams)
  File "/usr/share/vdsm/storage/sp.py", line 509, in _acquireTemporaryClusterLock
    msd.acquireHostId(self.id)
  File "/usr/share/vdsm/storage/sd.py", line 436, in acquireHostId
    self._clusterLock.acquireHostId(hostId, async)
  File "/usr/share/vdsm/storage/clusterlock.py", line 187, in acquireHostId
    raise se.AcquireHostIdFailure(self._sdUUID, e)
AcquireHostIdFailure: Cannot acquire host id: ('1083422e-a5db-41b6-b667-b9ef1ef244f0', SanlockException(-203, 'Sanlock lockspace add failure', 'Sanlock exception'))
Thread-182::DEBUG::2013-03-20 21:46:22,910::task::852::TaskManager.Task::(_run) Task=`e494d4ca-3f39-4bf0-aa23-0c69abf1c03c`::Task._run: e494d4ca-3f39-4bf0-aa23-0c69abf1c03c (None, '5849b030-626e-47cb-ad90-3ce782d831b3', 'Default', '1083422e-a5db-41b6-b667-b9ef1ef244f0', ['1083422e-a5db-41b6-b667-b9ef1ef244f0'], 16, None, 5, 60, 10, 3) {} failed - stopping task
Thread-182::DEBUG::2013-03-20 21:46:22,911::task::1177::TaskManager.Task::(stop) Task=`e494d4ca-3f39-4bf0-aa23-0c69abf1c03c`::stopping in state preparing (force False)
Thread-182::DEBUG::2013-03-20 21:46:22,911::task::957::TaskManager.Task::(_decref) Task=`e494d4ca-3f39-4bf0-aa23-0c69abf1c03c`::ref 1 aborting True
Thread-182::INFO::2013-03-20 21:46:22,911::task::1134::TaskManager.Task::(prepare) Task=`e494d4ca-3f39-4bf0-aa23-0c69abf1c03c`::aborting: Task is aborted: 'Cannot acquire host id' - code 661
Thread-182::DEBUG::2013-03-20 21:46:22,911::task::1139::TaskManager.Task::(prepare) Task=`e494d4ca-3f39-4bf0-aa23-0c69abf1c03c`::Prepare: aborted: Cannot acquire host id
Thread-182::DEBUG::2013-03-20 21:46:22,911::task::957::TaskManager.Task::(_decref) Task=`e494d4ca-3f39-4bf0-aa23-0c69abf1c03c`::ref 0 aborting True
Thread-182::DEBUG::2013-03-20 21:46:22,912::task::892::TaskManager.Task::(_doAbort) Task=`e494d4ca-3f39-4bf0-aa23-0c69abf1c03c`::Task._doAbort: force False
Thread-182::DEBUG::2013-03-20 21:46:22,912::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-182::DEBUG::2013-03-20 21:46:22,912::task::568::TaskManager.Task::(_updateState) Task=`e494d4ca-3f39-4bf0-aa23-0c69abf1c03c`::moving from state preparing -> state aborting
Thread-182::DEBUG::2013-03-20 21:46:22,912::task::523::TaskManager.Task::(__state_aborting) Task=`e494d4ca-3f39-4bf0-aa23-0c69abf1c03c`::_aborting: recover policy none
Thread-182::DEBUG::2013-03-20 21:46:22,912::task::568::TaskManager.Task::(_updateState) Task=`e494d4ca-3f39-4bf0-aa23-0c69abf1c03c`::moving from state aborting -> state failed
Thread-182::DEBUG::2013-03-20 21:46:22,912::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.5849b030-626e-47cb-ad90-3ce782d831b3': < ResourceRef 'Storage.5849b030-626e-47cb-ad90-3ce782d831b3', isValid: 'True' obj: 'None'>, 'Storage.1083422e-a5db-41b6-b667-b9ef1ef244f0': < ResourceRef 'Storage.1083422e-a5db-41b6-b667-b9ef1ef244f0', isValid: 'True' obj: 'None'>}
Thread-182::DEBUG::2013-03-20 21:46:22,913::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-182::DEBUG::2013-03-20 21:46:22,913::resourceManager::557::ResourceManager::(releaseResource) Trying to release resource 'Storage.5849b030-626e-47cb-ad90-3ce782d831b3'
Thread-182::DEBUG::2013-03-20 21:46:22,913::resourceManager::573::ResourceManager::(releaseResource) Released resource 'Storage.5849b030-626e-47cb-ad90-3ce782d831b3' (0 active users)
Thread-182::DEBUG::2013-03-20 21:46:22,913::resourceManager::578::ResourceManager::(releaseResource) Resource 'Storage.5849b030-626e-47cb-ad90-3ce782d831b3' is free, finding out if anyone is waiting for it.
Thread-182::DEBUG::2013-03-20 21:46:22,914::resourceManager::585::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.5849b030-626e-47cb-ad90-3ce782d831b3', Clearing records.
Thread-182::DEBUG::2013-03-20 21:46:22,914::resourceManager::557::ResourceManager::(releaseResource) Trying to release resource 'Storage.1083422e-a5db-41b6-b667-b9ef1ef244f0'
Thread-182::DEBUG::2013-03-20 21:46:22,914::resourceManager::573::ResourceManager::(releaseResource) Released resource 'Storage.1083422e-a5db-41b6-b667-b9ef1ef244f0' (0 active users)
Thread-182::DEBUG::2013-03-20 21:46:22,914::resourceManager::578::ResourceManager::(releaseResource) Resource 'Storage.1083422e-a5db-41b6-b667-b9ef1ef244f0' is free, finding out if anyone is waiting for it.
Thread-182::DEBUG::2013-03-20 21:46:22,914::resourceManager::585::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.1083422e-a5db-41b6-b667-b9ef1ef244f0', Clearing records.
Thread-182::ERROR::2013-03-20 21:46:22,915::dispatcher::67::Storage.Dispatcher.Protect::(run) {'status': {'message': "Cannot acquire host id: ('1083422e-a5db-41b6-b667-b9ef1ef244f0', SanlockException(-203, 'Sanlock lockspace add failure', 'Sanlock exception'))", 'code': 661}}
Thread-199::DEBUG::2013-03-20 21:46:32,028::task::568::TaskManager.Task::(_updateState) Task=`93aba6f0-dbd7-402e-967a-843ffacbccfd`::moving from state init -> state preparing
Thread-199::INFO::2013-03-20 21:46:32,029::logUtils::41::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-199::INFO::2013-03-20 21:46:32,029::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-199::DEBUG::2013-03-20 21:46:32,029::task::1151::TaskManager.Task::(prepare) Task=`93aba6f0-dbd7-402e-967a-843ffacbccfd`::finished: {}
Thread-199::DEBUG::2013-03-20 21:46:32,029::task::568::TaskManager.Task::(_updateState) Task=`93aba6f0-dbd7-402e-967a-843ffacbccfd`::moving from state preparing -> state finished
Thread-199::DEBUG::2013-03-20 21:46:32,030::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-199::DEBUG::2013-03-20 21:46:32,030::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-199::DEBUG::2013-03-20 21:46:32,030::task::957::TaskManager.Task::(_decref) Task=`93aba6f0-dbd7-402e-967a-843ffacbccfd`::ref 0 aborting False
Thread-205::DEBUG::2013-03-20 21:46:42,086::task::568::TaskManager.Task::(_updateState) Task=`bc186135-a7b3-4f90-8a5f-a78654fa6014`::moving from state init -> state preparing
Thread-205::INFO::2013-03-20 21:46:42,087::logUtils::41::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-205::INFO::2013-03-20 21:46:42,087::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-205::DEBUG::2013-03-20 21:46:42,087::task::1151::TaskManager.Task::(prepare) Task=`bc186135-a7b3-4f90-8a5f-a78654fa6014`::finished: {}
Thread-205::DEBUG::2013-03-20 21:46:42,088::task::568::TaskManager.Task::(_updateState) Task=`bc186135-a7b3-4f90-8a5f-a78654fa6014`::moving from state preparing -> state finished
Thread-205::DEBUG::2013-03-20 21:46:42,088::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-205::DEBUG::2013-03-20 21:46:42,088::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-205::DEBUG::2013-03-20 21:46:42,088::task::957::TaskManager.Task::(_decref) Task=`bc186135-a7b3-4f90-8a5f-a78654fa6014`::ref 0 aborting False
Thread-211::DEBUG::2013-03-20 21:46:52,150::task::568::TaskManager.Task::(_updateState) Task=`b03983c3-0578-46bc-af36-15ee7216f0f0`::moving from state init -> state preparing
Thread-211::INFO::2013-03-20 21:46:52,151::logUtils::41::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-211::INFO::2013-03-20 21:46:52,151::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-211::DEBUG::2013-03-20 21:46:52,151::task::1151::TaskManager.Task::(prepare) Task=`b03983c3-0578-46bc-af36-15ee7216f0f0`::finished: {}
Thread-211::DEBUG::2013-03-20 21:46:52,152::task::568::TaskManager.Task::(_updateState) Task=`b03983c3-0578-46bc-af36-15ee7216f0f0`::moving from state preparing -> state finished
Thread-211::DEBUG::2013-03-20 21:46:52,152::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-211::DEBUG::2013-03-20 21:46:52,152::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-211::DEBUG::2013-03-20 21:46:52,152::task::957::TaskManager.Task::(_decref) Task=`b03983c3-0578-46bc-af36-15ee7216f0f0`::ref 0 aborting False
Thread-217::DEBUG::2013-03-20 21:47:02,210::task::568::TaskManager.Task::(_updateState) Task=`b180c22b-bd43-403d-8c73-a3ae440bcbc3`::moving from state init -> state preparing
Thread-217::INFO::2013-03-20 21:47:02,211::logUtils::41::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-217::INFO::2013-03-20 21:47:02,211::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-217::DEBUG::2013-03-20 21:47:02,211::task::1151::TaskManager.Task::(prepare) Task=`b180c22b-bd43-403d-8c73-a3ae440bcbc3`::finished: {}
Thread-217::DEBUG::2013-03-20 21:47:02,211::task::568::TaskManager.Task::(_updateState) Task=`b180c22b-bd43-403d-8c73-a3ae440bcbc3`::moving from state preparing -> state finished
Thread-217::DEBUG::2013-03-20 21:47:02,211::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-217::DEBUG::2013-03-20 21:47:02,211::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-217::DEBUG::2013-03-20 21:47:02,212::task::957::TaskManager.Task::(_decref) Task=`b180c22b-bd43-403d-8c73-a3ae440bcbc3`::ref 0 aborting False
Thread-223::DEBUG::2013-03-20 21:47:12,291::task::568::TaskManager.Task::(_updateState) Task=`b711094a-0945-4f0d-80c9-16f39024f02b`::moving from state init -> state preparing
Thread-223::INFO::2013-03-20 21:47:12,291::logUtils::41::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-223::INFO::2013-03-20 21:47:12,291::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-223::DEBUG::2013-03-20 21:47:12,292::task::1151::TaskManager.Task::(prepare) Task=`b711094a-0945-4f0d-80c9-16f39024f02b`::finished: {}
Thread-223::DEBUG::2013-03-20 21:47:12,292::task::568::TaskManager.Task::(_updateState) Task=`b711094a-0945-4f0d-80c9-16f39024f02b`::moving from state preparing -> state finished
Thread-223::DEBUG::2013-03-20 21:47:12,292::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-223::DEBUG::2013-03-20 21:47:12,292::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-223::DEBUG::2013-03-20 21:47:12,292::task::957::TaskManager.Task::(_decref) Task=`b711094a-0945-4f0d-80c9-16f39024f02b`::ref 0 aborting False
Thread-229::DEBUG::2013-03-20 21:47:22,353::task::568::TaskManager.Task::(_updateState) Task=`af2b84d6-bcae-45e4-b0e3-eb90d1c9b4a7`::moving from state init -> state preparing
Thread-229::INFO::2013-03-20 21:47:22,353::logUtils::41::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-229::INFO::2013-03-20 21:47:22,353::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-229::DEBUG::2013-03-20 21:47:22,354::task::1151::TaskManager.Task::(prepare) Task=`af2b84d6-bcae-45e4-b0e3-eb90d1c9b4a7`::finished: {}
Thread-229::DEBUG::2013-03-20 21:47:22,354::task::568::TaskManager.Task::(_updateState) Task=`af2b84d6-bcae-45e4-b0e3-eb90d1c9b4a7`::moving from state preparing -> state finished
Thread-229::DEBUG::2013-03-20 21:47:22,354::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-229::DEBUG::2013-03-20 21:47:22,354::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-229::DEBUG::2013-03-20 21:47:22,354::task::957::TaskManager.Task::(_decref) Task=`af2b84d6-bcae-45e4-b0e3-eb90d1c9b4a7`::ref 0 aborting False
Thread-235::DEBUG::2013-03-20 21:47:32,434::task::568::TaskManager.Task::(_updateState) Task=`f4ee9ba2-97c9-4c57-9fb5-0fe0c77a80af`::moving from state init -> state preparing
Thread-235::INFO::2013-03-20 21:47:32,435::logUtils::41::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-235::INFO::2013-03-20 21:47:32,435::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-235::DEBUG::2013-03-20 21:47:32,435::task::1151::TaskManager.Task::(prepare) Task=`f4ee9ba2-97c9-4c57-9fb5-0fe0c77a80af`::finished: {}
Thread-235::DEBUG::2013-03-20 21:47:32,435::task::568::TaskManager.Task::(_updateState) Task=`f4ee9ba2-97c9-4c57-9fb5-0fe0c77a80af`::moving from state preparing -> state finished
Thread-235::DEBUG::2013-03-20 21:47:32,435::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-235::DEBUG::2013-03-20 21:47:32,435::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-235::DEBUG::2013-03-20 21:47:32,436::task::957::TaskManager.Task::(_decref) Task=`f4ee9ba2-97c9-4c57-9fb5-0fe0c77a80af`::ref 0 aborting False
Thread-241::DEBUG::2013-03-20 21:47:42,495::task::568::TaskManager.Task::(_updateState) Task=`9e143298-1656-4b1e-a57d-29f9841d711a`::moving from state init -> state preparing
Thread-241::INFO::2013-03-20 21:47:42,496::logUtils::41::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-241::INFO::2013-03-20 21:47:42,496::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-241::DEBUG::2013-03-20 21:47:42,496::task::1151::TaskManager.Task::(prepare) Task=`9e143298-1656-4b1e-a57d-29f9841d711a`::finished: {}
Thread-241::DEBUG::2013-03-20 21:47:42,497::task::568::TaskManager.Task::(_updateState) Task=`9e143298-1656-4b1e-a57d-29f9841d711a`::moving from state preparing -> state finished
Thread-241::DEBUG::2013-03-20 21:47:42,497::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-241::DEBUG::2013-03-20 21:47:42,497::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-241::DEBUG::2013-03-20 21:47:42,497::task::957::TaskManager.Task::(_decref) Task=`9e143298-1656-4b1e-a57d-29f9841d711a`::ref 0 aborting False
Thread-247::DEBUG::2013-03-20 21:47:52,555::task::568::TaskManager.Task::(_updateState) Task=`f40a9d5c-5bcb-4406-92f7-5bdac2c21e57`::moving from state init -> state preparing
Thread-247::INFO::2013-03-20 21:47:52,556::logUtils::41::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-247::INFO::2013-03-20 21:47:52,556::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-247::DEBUG::2013-03-20 21:47:52,556::task::1151::TaskManager.Task::(prepare) Task=`f40a9d5c-5bcb-4406-92f7-5bdac2c21e57`::finished: {}
Thread-247::DEBUG::2013-03-20 21:47:52,556::task::568::TaskManager.Task::(_updateState) Task=`f40a9d5c-5bcb-4406-92f7-5bdac2c21e57`::moving from state preparing -> state finished
Thread-247::DEBUG::2013-03-20 21:47:52,556::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-247::DEBUG::2013-03-20 21:47:52,557::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-247::DEBUG::2013-03-20 21:47:52,557::task::957::TaskManager.Task::(_decref) Task=`f40a9d5c-5bcb-4406-92f7-5bdac2c21e57`::ref 0 aborting False
Thread-253::DEBUG::2013-03-20 21:48:02,613::task::568::TaskManager.Task::(_updateState) Task=`03e9971a-7256-491b-ad77-221373002e13`::moving from state init -> state preparing
Thread-253::INFO::2013-03-20 21:48:02,613::logUtils::41::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-253::INFO::2013-03-20 21:48:02,613::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-253::DEBUG::2013-03-20 21:48:02,613::task::1151::TaskManager.Task::(prepare) Task=`03e9971a-7256-491b-ad77-221373002e13`::finished: {}
Thread-253::DEBUG::2013-03-20 21:48:02,613::task::568::TaskManager.Task::(_updateState) Task=`03e9971a-7256-491b-ad77-221373002e13`::moving from state preparing -> state finished
Thread-253::DEBUG::2013-03-20 21:48:02,613::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-253::DEBUG::2013-03-20 21:48:02,613::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-253::DEBUG::2013-03-20 21:48:02,613::task::957::TaskManager.Task::(_decref) Task=`03e9971a-7256-491b-ad77-221373002e13`::ref 0 aborting False
Thread-259::DEBUG::2013-03-20 21:48:12,669::task::568::TaskManager.Task::(_updateState) Task=`3e066925-4c21-4a80-bdd2-8e63aa029f5e`::moving from state init -> state preparing
Thread-259::INFO::2013-03-20 21:48:12,669::logUtils::41::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-259::INFO::2013-03-20 21:48:12,669::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-259::DEBUG::2013-03-20 21:48:12,669::task::1151::TaskManager.Task::(prepare) Task=`3e066925-4c21-4a80-bdd2-8e63aa029f5e`::finished: {}
Thread-259::DEBUG::2013-03-20 21:48:12,670::task::568::TaskManager.Task::(_updateState) Task=`3e066925-4c21-4a80-bdd2-8e63aa029f5e`::moving from state preparing -> state finished
Thread-259::DEBUG::2013-03-20 21:48:12,670::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-259::DEBUG::2013-03-20 21:48:12,670::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-259::DEBUG::2013-03-20 21:48:12,670::task::957::TaskManager.Task::(_decref) Task=`3e066925-4c21-4a80-bdd2-8e63aa029f5e`::ref 0 aborting False
Thread-265::DEBUG::2013-03-20 21:48:22,730::task::568::TaskManager.Task::(_updateState) Task=`e0d6731d-3541-4b03-9fbb-22c01f2268c6`::moving from state init -> state preparing
Thread-265::INFO::2013-03-20 21:48:22,731::logUtils::41::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-265::INFO::2013-03-20 21:48:22,731::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-265::DEBUG::2013-03-20 21:48:22,731::task::1151::TaskManager.Task::(prepare) Task=`e0d6731d-3541-4b03-9fbb-22c01f2268c6`::finished: {}
Thread-265::DEBUG::2013-03-20 21:48:22,731::task::568::TaskManager.Task::(_updateState) Task=`e0d6731d-3541-4b03-9fbb-22c01f2268c6`::moving from state preparing -> state finished
Thread-265::DEBUG::2013-03-20 21:48:22,731::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-265::DEBUG::2013-03-20 21:48:22,732::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-265::DEBUG::2013-03-20 21:48:22,732::task::957::TaskManager.Task::(_decref) Task=`e0d6731d-3541-4b03-9fbb-22c01f2268c6`::ref 0 aborting False
Thread-271::DEBUG::2013-03-20 21:48:32,791::task::568::TaskManager.Task::(_updateState) Task=`007df3d2-a95b-4a3a-bf41-798acef9f8df`::moving from state init -> state preparing
Thread-271::INFO::2013-03-20 21:48:32,792::logUtils::41::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-271::INFO::2013-03-20 21:48:32,792::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-271::DEBUG::2013-03-20 21:48:32,792::task::1151::TaskManager.Task::(prepare) Task=`007df3d2-a95b-4a3a-bf41-798acef9f8df`::finished: {}
Thread-271::DEBUG::2013-03-20 21:48:32,792::task::568::TaskManager.Task::(_updateState) Task=`007df3d2-a95b-4a3a-bf41-798acef9f8df`::moving from state preparing -> state finished
Thread-271::DEBUG::2013-03-20 21:48:32,792::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-271::DEBUG::2013-03-20 21:48:32,793::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-271::DEBUG::2013-03-20 21:48:32,793::task::957::TaskManager.Task::(_decref) Task=`007df3d2-a95b-4a3a-bf41-798acef9f8df`::ref 0 aborting False
Thread-277::DEBUG::2013-03-20 21:48:42,847::task::568::TaskManager.Task::(_updateState) Task=`b4b4dbf5-a8b0-4d8b-ab11-c67ef4efba25`::moving from state init -> state preparing
Thread-277::INFO::2013-03-20 21:48:42,848::logUtils::41::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-277::INFO::2013-03-20 21:48:42,848::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-277::DEBUG::2013-03-20 21:48:42,848::task::1151::TaskManager.Task::(prepare) Task=`b4b4dbf5-a8b0-4d8b-ab11-c67ef4efba25`::finished: {}
Thread-277::DEBUG::2013-03-20 21:48:42,848::task::568::TaskManager.Task::(_updateState) Task=`b4b4dbf5-a8b0-4d8b-ab11-c67ef4efba25`::moving from state preparing -> state finished
Thread-277::DEBUG::2013-03-20 21:48:42,849::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-277::DEBUG::2013-03-20 21:48:42,849::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-277::DEBUG::2013-03-20 21:48:42,849::task::957::TaskManager.Task::(_decref) Task=`b4b4dbf5-a8b0-4d8b-ab11-c67ef4efba25`::ref 0 aborting False
Thread-283::DEBUG::2013-03-20 21:48:52,906::task::568::TaskManager.Task::(_updateState) Task=`b8124879-4947-4648-b6e7-3936abc2cb3c`::moving from state init -> state preparing
Thread-283::INFO::2013-03-20 21:48:52,906::logUtils::41::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-283::INFO::2013-03-20 21:48:52,906::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-283::DEBUG::2013-03-20 21:48:52,907::task::1151::TaskManager.Task::(prepare) Task=`b8124879-4947-4648-b6e7-3936abc2cb3c`::finished: {}
Thread-283::DEBUG::2013-03-20 21:48:52,907::task::568::TaskManager.Task::(_updateState) Task=`b8124879-4947-4648-b6e7-3936abc2cb3c`::moving from state preparing -> state finished
Thread-283::DEBUG::2013-03-20 21:48:52,907::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-283::DEBUG::2013-03-20 21:48:52,907::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-283::DEBUG::2013-03-20 21:48:52,907::task::957::TaskManager.Task::(_decref) Task=`b8124879-4947-4648-b6e7-3936abc2cb3c`::ref 0 aborting False
Thread-289::DEBUG::2013-03-20 21:49:02,956::task::568::TaskManager.Task::(_updateState) Task=`9862ec60-f002-4877-9902-5ad0f1caecf7`::moving from state init -> state preparing
Thread-289::INFO::2013-03-20 21:49:02,957::logUtils::41::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-289::INFO::2013-03-20 21:49:02,957::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-289::DEBUG::2013-03-20 21:49:02,957::task::1151::TaskManager.Task::(prepare) Task=`9862ec60-f002-4877-9902-5ad0f1caecf7`::finished: {}
Thread-289::DEBUG::2013-03-20 21:49:02,957::task::568::TaskManager.Task::(_updateState) Task=`9862ec60-f002-4877-9902-5ad0f1caecf7`::moving from state preparing -> state finished
Thread-289::DEBUG::2013-03-20 21:49:02,957::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-289::DEBUG::2013-03-20 21:49:02,957::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-289::DEBUG::2013-03-20 21:49:02,958::task::957::TaskManager.Task::(_decref) Task=`9862ec60-f002-4877-9902-5ad0f1caecf7`::ref 0 aborting False
Thread-295::DEBUG::2013-03-20 21:49:13,015::task::568::TaskManager.Task::(_updateState) Task=`76ecc06f-86ad-4346-bb81-07dae398350f`::moving from state init -> state preparing
Thread-295::INFO::2013-03-20 21:49:13,016::logUtils::41::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-295::INFO::2013-03-20 21:49:13,016::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-295::DEBUG::2013-03-20 21:49:13,016::task::1151::TaskManager.Task::(prepare) Task=`76ecc06f-86ad-4346-bb81-07dae398350f`::finished: {}
Thread-295::DEBUG::2013-03-20 21:49:13,016::task::568::TaskManager.Task::(_updateState) Task=`76ecc06f-86ad-4346-bb81-07dae398350f`::moving from state preparing -> state finished
Thread-295::DEBUG::2013-03-20 21:49:13,016::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-295::DEBUG::2013-03-20 21:49:13,017::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-295::DEBUG::2013-03-20 21:49:13,017::task::957::TaskManager.Task::(_decref) Task=`76ecc06f-86ad-4346-bb81-07dae398350f`::ref 0 aborting False
Thread-301::DEBUG::2013-03-20 21:49:23,071::task::568::TaskManager.Task::(_updateState) Task=`1b8465bd-9fd1-40d0-baaa-8c76905978fb`::moving from state init -> state preparing
Thread-301::INFO::2013-03-20 21:49:23,072::logUtils::41::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-301::INFO::2013-03-20 21:49:23,072::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-301::DEBUG::2013-03-20 21:49:23,072::task::1151::TaskManager.Task::(prepare) Task=`1b8465bd-9fd1-40d0-baaa-8c76905978fb`::finished: {}
Thread-301::DEBUG::2013-03-20 21:49:23,072::task::568::TaskManager.Task::(_updateState) Task=`1b8465bd-9fd1-40d0-baaa-8c76905978fb`::moving from state preparing -> state finished
Thread-301::DEBUG::2013-03-20 21:49:23,072::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-301::DEBUG::2013-03-20 21:49:23,073::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-301::DEBUG::2013-03-20 21:49:23,073::task::957::TaskManager.Task::(_decref) Task=`1b8465bd-9fd1-40d0-baaa-8c76905978fb`::ref 0 aborting False
Thread-307::DEBUG::2013-03-20 21:49:33,130::task::568::TaskManager.Task::(_updateState) Task=`304fcab4-f102-40d8-8570-ce3b57e02c64`::moving from state init -> state preparing
Thread-307::INFO::2013-03-20 21:49:33,131::logUtils::41::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-307::INFO::2013-03-20 21:49:33,131::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-307::DEBUG::2013-03-20 21:49:33,131::task::1151::TaskManager.Task::(prepare) Task=`304fcab4-f102-40d8-8570-ce3b57e02c64`::finished: {}
Thread-307::DEBUG::2013-03-20 21:49:33,132::task::568::TaskManager.Task::(_updateState) Task=`304fcab4-f102-40d8-8570-ce3b57e02c64`::moving from state preparing -> state finished
Thread-307::DEBUG::2013-03-20 21:49:33,132::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-307::DEBUG::2013-03-20 21:49:33,132::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-307::DEBUG::2013-03-20 21:49:33,132::task::957::TaskManager.Task::(_decref) Task=`304fcab4-f102-40d8-8570-ce3b57e02c64`::ref 0 aborting False
Thread-313::DEBUG::2013-03-20 21:49:43,189::task::568::TaskManager.Task::(_updateState) Task=`ee2b2cdb-23b0-4312-88b2-063559b19a97`::moving from state init -> state preparing
Thread-313::INFO::2013-03-20 21:49:43,190::logUtils::41::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-313::INFO::2013-03-20 21:49:43,190::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-313::DEBUG::2013-03-20 21:49:43,190::task::1151::TaskManager.Task::(prepare) Task=`ee2b2cdb-23b0-4312-88b2-063559b19a97`::finished: {}
Thread-313::DEBUG::2013-03-20 21:49:43,190::task::568::TaskManager.Task::(_updateState) Task=`ee2b2cdb-23b0-4312-88b2-063559b19a97`::moving from state preparing -> state finished
Thread-313::DEBUG::2013-03-20 21:49:43,190::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-313::DEBUG::2013-03-20 21:49:43,190::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-313::DEBUG::2013-03-20 21:49:43,191::task::957::TaskManager.Task::(_decref) Task=`ee2b2cdb-23b0-4312-88b2-063559b19a97`::ref 0 aborting False
Thread-319::DEBUG::2013-03-20 21:49:53,251::task::568::TaskManager.Task::(_updateState) Task=`edd1492b-35f3-4d49-9e1b-b6ccdee3fd42`::moving from state init -> state preparing
Thread-319::INFO::2013-03-20 21:49:53,251::logUtils::41::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-319::INFO::2013-03-20 21:49:53,251::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-319::DEBUG::2013-03-20 21:49:53,251::task::1151::TaskManager.Task::(prepare) Task=`edd1492b-35f3-4d49-9e1b-b6ccdee3fd42`::finished: {}
Thread-319::DEBUG::2013-03-20 21:49:53,252::task::568::TaskManager.Task::(_updateState) Task=`edd1492b-35f3-4d49-9e1b-b6ccdee3fd42`::moving from state preparing -> state finished
Thread-319::DEBUG::2013-03-20 21:49:53,252::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-319::DEBUG::2013-03-20 21:49:53,252::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-319::DEBUG::2013-03-20 21:49:53,252::task::957::TaskManager.Task::(_decref) Task=`edd1492b-35f3-4d49-9e1b-b6ccdee3fd42`::ref 0 aborting False
Thread-325::DEBUG::2013-03-20 21:50:03,309::task::568::TaskManager.Task::(_updateState) Task=`613d2d1b-c9c1-4161-a565-5f7b706b507b`::moving from state init -> state preparing
Thread-325::INFO::2013-03-20 21:50:03,310::logUtils::41::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-325::INFO::2013-03-20 21:50:03,310::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-325::DEBUG::2013-03-20 21:50:03,310::task::1151::TaskManager.Task::(prepare) Task=`613d2d1b-c9c1-4161-a565-5f7b706b507b`::finished: {}
Thread-325::DEBUG::2013-03-20 21:50:03,310::task::568::TaskManager.Task::(_updateState) Task=`613d2d1b-c9c1-4161-a565-5f7b706b507b`::moving from state preparing -> state finished
Thread-325::DEBUG::2013-03-20 21:50:03,310::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-325::DEBUG::2013-03-20 21:50:03,311::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-325::DEBUG::2013-03-20 21:50:03,311::task::957::TaskManager.Task::(_decref) Task=`613d2d1b-c9c1-4161-a565-5f7b706b507b`::ref 0 aborting False
Thread-331::DEBUG::2013-03-20 21:50:13,364::task::568::TaskManager.Task::(_updateState) Task=`0e6876c1-e299-4dce-8dc4-749d42a6a1da`::moving from state init -> state preparing
Thread-331::INFO::2013-03-20 21:50:13,365::logUtils::41::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-331::INFO::2013-03-20 21:50:13,365::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-331::DEBUG::2013-03-20 21:50:13,365::task::1151::TaskManager.Task::(prepare) Task=`0e6876c1-e299-4dce-8dc4-749d42a6a1da`::finished: {}
Thread-331::DEBUG::2013-03-20 21:50:13,365::task::568::TaskManager.Task::(_updateState) Task=`0e6876c1-e299-4dce-8dc4-749d42a6a1da`::moving from state preparing -> state finished
Thread-331::DEBUG::2013-03-20 21:50:13,366::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-331::DEBUG::2013-03-20 21:50:13,366::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-331::DEBUG::2013-03-20 21:50:13,366::task::957::TaskManager.Task::(_decref) Task=`0e6876c1-e299-4dce-8dc4-749d42a6a1da`::ref 0 aborting False
Thread-337::DEBUG::2013-03-20 21:50:23,423::task::568::TaskManager.Task::(_updateState) Task=`1e925b67-70a2-46bc-8593-583a6b75711f`::moving from state init -> state preparing
Thread-337::INFO::2013-03-20 21:50:23,424::logUtils::41::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-337::INFO::2013-03-20 21:50:23,424::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-337::DEBUG::2013-03-20 21:50:23,424::task::1151::TaskManager.Task::(prepare) Task=`1e925b67-70a2-46bc-8593-583a6b75711f`::finished: {}
Thread-337::DEBUG::2013-03-20 21:50:23,424::task::568::TaskManager.Task::(_updateState) Task=`1e925b67-70a2-46bc-8593-583a6b75711f`::moving from state preparing -> state finished
Thread-337::DEBUG::2013-03-20 21:50:23,424::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-337::DEBUG::2013-03-20 21:50:23,424::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-337::DEBUG::2013-03-20 21:50:23,425::task::957::TaskManager.Task::(_decref) Task=`1e925b67-70a2-46bc-8593-583a6b75711f`::ref 0 aborting False
Thread-343::DEBUG::2013-03-20 21:50:33,478::task::568::TaskManager.Task::(_updateState) Task=`d8d9a4e1-83ac-4f63-b9b3-86cfe90973de`::moving from state init -> state preparing
Thread-343::INFO::2013-03-20 21:50:33,479::logUtils::41::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-343::INFO::2013-03-20 21:50:33,479::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-343::DEBUG::2013-03-20 21:50:33,479::task::1151::TaskManager.Task::(prepare) Task=`d8d9a4e1-83ac-4f63-b9b3-86cfe90973de`::finished: {}
Thread-343::DEBUG::2013-03-20 21:50:33,479::task::568::TaskManager.Task::(_updateState) Task=`d8d9a4e1-83ac-4f63-b9b3-86cfe90973de`::moving from state preparing -> state finished
Thread-343::DEBUG::2013-03-20 21:50:33,479::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-343::DEBUG::2013-03-20 21:50:33,479::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-343::DEBUG::2013-03-20 21:50:33,479::task::957::TaskManager.Task::(_decref) Task=`d8d9a4e1-83ac-4f63-b9b3-86cfe90973de`::ref 0 aborting False
Thread-349::DEBUG::2013-03-20 21:50:43,532::task::568::TaskManager.Task::(_updateState) Task=`f087b2df-6323-49e5-afe8-60d94c7b3ba5`::moving from state init -> state preparing
Thread-349::INFO::2013-03-20 21:50:43,532::logUtils::41::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-349::INFO::2013-03-20 21:50:43,532::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-349::DEBUG::2013-03-20 21:50:43,532::task::1151::TaskManager.Task::(prepare) Task=`f087b2df-6323-49e5-afe8-60d94c7b3ba5`::finished: {}
Thread-349::DEBUG::2013-03-20 21:50:43,533::task::568::TaskManager.Task::(_updateState) Task=`f087b2df-6323-49e5-afe8-60d94c7b3ba5`::moving from state preparing -> state finished
Thread-349::DEBUG::2013-03-20 21:50:43,533::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-349::DEBUG::2013-03-20 21:50:43,533::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-349::DEBUG::2013-03-20 21:50:43,533::task::957::TaskManager.Task::(_decref) Task=`f087b2df-6323-49e5-afe8-60d94c7b3ba5`::ref 0 aborting False
Thread-355::DEBUG::2013-03-20 21:50:53,588::task::568::TaskManager.Task::(_updateState) Task=`4011ee46-f61b-462a-946e-7d2be852037f`::moving from state init -> state preparing
Thread-355::INFO::2013-03-20 21:50:53,589::logUtils::41::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-355::INFO::2013-03-20 21:50:53,589::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-355::DEBUG::2013-03-20 21:50:53,589::task::1151::TaskManager.Task::(prepare) Task=`4011ee46-f61b-462a-946e-7d2be852037f`::finished: {}
Thread-355::DEBUG::2013-03-20 21:50:53,589::task::568::TaskManager.Task::(_updateState) Task=`4011ee46-f61b-462a-946e-7d2be852037f`::moving from state preparing -> state finished
Thread-355::DEBUG::2013-03-20 21:50:53,589::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-355::DEBUG::2013-03-20 21:50:53,590::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-355::DEBUG::2013-03-20 21:50:53,590::task::957::TaskManager.Task::(_decref) Task=`4011ee46-f61b-462a-946e-7d2be852037f`::ref 0 aborting False
Thread-361::DEBUG::2013-03-20 21:51:03,646::task::568::TaskManager.Task::(_updateState) Task=`1fa16674-03c9-4b5e-a87d-15af55f7f23e`::moving from state init -> state preparing
Thread-361::INFO::2013-03-20 21:51:03,647::logUtils::41::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-361::INFO::2013-03-20 21:51:03,647::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-361::DEBUG::2013-03-20 21:51:03,647::task::1151::TaskManager.Task::(prepare) Task=`1fa16674-03c9-4b5e-a87d-15af55f7f23e`::finished: {}
Thread-361::DEBUG::2013-03-20 21:51:03,647::task::568::TaskManager.Task::(_updateState) Task=`1fa16674-03c9-4b5e-a87d-15af55f7f23e`::moving from state preparing -> state finished
Thread-361::DEBUG::2013-03-20 21:51:03,647::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-361::DEBUG::2013-03-20 21:51:03,648::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-361::DEBUG::2013-03-20 21:51:03,648::task::957::TaskManager.Task::(_decref) Task=`1fa16674-03c9-4b5e-a87d-15af55f7f23e`::ref 0 aborting False
Thread-367::DEBUG::2013-03-20 21:51:13,701::task::568::TaskManager.Task::(_updateState) Task=`c21ea5be-f062-49d1-a6e6-979455ecfe14`::moving from state init -> state preparing
Thread-367::INFO::2013-03-20 21:51:13,702::logUtils::41::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-367::INFO::2013-03-20 21:51:13,702::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-367::DEBUG::2013-03-20 21:51:13,702::task::1151::TaskManager.Task::(prepare) Task=`c21ea5be-f062-49d1-a6e6-979455ecfe14`::finished: {}
Thread-367::DEBUG::2013-03-20 21:51:13,702::task::568::TaskManager.Task::(_updateState) Task=`c21ea5be-f062-49d1-a6e6-979455ecfe14`::moving from state preparing -> state finished
Thread-367::DEBUG::2013-03-20 21:51:13,703::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-367::DEBUG::2013-03-20 21:51:13,703::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-367::DEBUG::2013-03-20 21:51:13,703::task::957::TaskManager.Task::(_decref) Task=`c21ea5be-f062-49d1-a6e6-979455ecfe14`::ref 0 aborting False
Thread-373::DEBUG::2013-03-20 21:51:23,759::task::568::TaskManager.Task::(_updateState) Task=`f223df7a-92b2-477b-9e61-b4acee6c8233`::moving from state init -> state preparing
Thread-373::INFO::2013-03-20 21:51:23,759::logUtils::41::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-373::INFO::2013-03-20 21:51:23,759::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-373::DEBUG::2013-03-20 21:51:23,759::task::1151::TaskManager.Task::(prepare) Task=`f223df7a-92b2-477b-9e61-b4acee6c8233`::finished: {}
Thread-373::DEBUG::2013-03-20 21:51:23,760::task::568::TaskManager.Task::(_updateState) Task=`f223df7a-92b2-477b-9e61-b4acee6c8233`::moving from state preparing -> state finished
Thread-373::DEBUG::2013-03-20 21:51:23,760::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-373::DEBUG::2013-03-20 21:51:23,760::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-373::DEBUG::2013-03-20 21:51:23,760::task::957::TaskManager.Task::(_decref) Task=`f223df7a-92b2-477b-9e61-b4acee6c8233`::ref 0 aborting False