Thread-13::DEBUG::2014-11-25 14:55:06,359::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-13::DEBUG::2014-11-25 14:55:06,359::task::993::Storage.TaskManager.Task::(_decref) Task=`24ef8c12-ef59-4ef4-9a67-561a3dbd189a`::ref 0 aborting False Thread-13::DEBUG::2014-11-25 14:55:21,575::task::595::Storage.TaskManager.Task::(_updateState) Task=`07cec52f-6f3b-46ec-957e-d105353168b6`::moving from state init -> state preparing Thread-13::INFO::2014-11-25 14:55:21,575::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None) Thread-13::INFO::2014-11-25 14:55:21,576::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {} Thread-13::DEBUG::2014-11-25 14:55:21,576::task::1191::Storage.TaskManager.Task::(prepare) Task=`07cec52f-6f3b-46ec-957e-d105353168b6`::finished: {} Thread-13::DEBUG::2014-11-25 14:55:21,576::task::595::Storage.TaskManager.Task::(_updateState) Task=`07cec52f-6f3b-46ec-957e-d105353168b6`::moving from state preparing -> state finished Thread-13::DEBUG::2014-11-25 14:55:21,576::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-13::DEBUG::2014-11-25 14:55:21,576::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-13::DEBUG::2014-11-25 14:55:21,576::task::993::Storage.TaskManager.Task::(_decref) Task=`07cec52f-6f3b-46ec-957e-d105353168b6`::ref 0 aborting False Thread-13::DEBUG::2014-11-25 14:55:36,788::BindingXMLRPC::1132::vds::(wrapper) client [10.10.10.2]::call getCapabilities with () {} flowID [5279acc6] Thread-13::DEBUG::2014-11-25 14:55:36,791::utils::738::root::(execCmd) /sbin/ip route show to 0.0.0.0/0 table all (cwd None) Thread-13::DEBUG::2014-11-25 14:55:36,798::utils::758::root::(execCmd) SUCCESS: = ''; = 0 Thread-13::DEBUG::2014-11-25 14:55:36,827::caps::728::root::(_getKeyPackages) rpm package ('gluster-swift',) not found Thread-13::DEBUG::2014-11-25 14:55:36,831::caps::728::root::(_getKeyPackages) rpm package ('gluster-swift-object',) not found Thread-13::DEBUG::2014-11-25 14:55:36,831::caps::728::root::(_getKeyPackages) rpm package ('gluster-swift-plugin',) not found Thread-13::DEBUG::2014-11-25 14:55:36,836::caps::728::root::(_getKeyPackages) rpm package ('gluster-swift-account',) not found Thread-13::DEBUG::2014-11-25 14:55:36,837::caps::728::root::(_getKeyPackages) rpm package ('gluster-swift-proxy',) not found Thread-13::DEBUG::2014-11-25 14:55:36,837::caps::728::root::(_getKeyPackages) rpm package ('gluster-swift-doc',) not found Thread-13::DEBUG::2014-11-25 14:55:36,837::caps::728::root::(_getKeyPackages) rpm package ('gluster-swift-container',) not found Thread-13::DEBUG::2014-11-25 14:55:36,838::caps::728::root::(_getKeyPackages) rpm package ('glusterfs-geo-replication',) not found Thread-13::DEBUG::2014-11-25 14:55:36,839::caps::646::root::(get) VirtioRNG DISABLED: libvirt version 0.10.2-29.el6_5.9 required >= 0.10.2-31 Thread-13::DEBUG::2014-11-25 14:55:36,842::BindingXMLRPC::1139::vds::(wrapper) return getCapabilities with {'status': {'message': 'Done', 'code': 0}, 'info': {'HBAInventory': {'iSCSI': [{'InitiatorName': 'iqn.1994-05.com.redhat:32151ce183c8'}], 'FC': []}, 'packages2': {'kernel': {'release': '431.el6.x86_64', 'buildtime': 1385061309.0, 'version': '2.6.32'}, 'glusterfs-rdma': {'release': '1.el6', 'buildtime': 1403622628L, 'version': '3.5.1'}, 'glusterfs-fuse': {'release': '1.el6', 'buildtime': 1403622628L, 'version': '3.5.1'}, 'spice-server': {'release': '6.el6_5.2', 'buildtime': 1402324637L, 'version': '0.12.4'}, 'vdsm': {'release': '1.gitdb83943.el6', 'buildtime': 1412784567L, 'version': '4.16.7'}, 'qemu-kvm': {'release': '2.415.el6_5.10', 'buildtime': 1402435700L, 'version': '0.12.1.2'}, 'qemu-img': {'release': '2.415.el6_5.10', 'buildtime': 1402435700L, 'version': '0.12.1.2'}, 'libvirt': {'release': '29.el6_5.9', 'buildtime': 1402404612L, 'version': '0.10.2'}, 'glusterfs': {'release': '1.el6', 'buildtime': 1403622628L, 'version': '3.5.1'}, 'mom': {'release': '2.el6', 'buildtime': 1403794344L, 'version': '0.4.1'}, 'glusterfs-server': {'release': '1.el6', 'buildtime': 1403622628L, 'version': '3.5.1'}}, 'numaNodeDistance': {'1': [20, 10], '0': [10, 20]}, 'cpuModel': 'Intel(R) Xeon(R) CPU X5650 @ 2.67GHz', 'liveMerge': 'false', 'hooks': {}, 'cpuSockets': '2', 'vmTypes': ['kvm'], 'selinux': {'mode': '1'}, 'kdumpStatus': 0, 'supportedProtocols': ['2.2', '2.3'], 'networks': {'ovirtmgmt': {'iface': u'bond0.10', 'addr': '43.252.176.16', 'bridged': False, 'ipv6addrs': ['fe80::62eb:69ff:fe20:b46c/64'], 'mtu': '1500', 'bootproto4': 'none', 'netmask': '255.255.255.0', 'ipv4addrs': ['43.252.176.16/24'], 'interface': u'bond0.10', 'ipv6gateway': '::', 'gateway': '43.252.176.1'}, 'Internal': {'iface': 'Internal', 'addr': '', 'cfg': {'DEFROUTE': 'no', 'HOTPLUG': 'no', 'MTU': '9000', 'DELAY': '0', 'NM_CONTROLLED': 'no', 'BOOTPROTO': 'none', 'STP': 'off', 'DEVICE': 'Internal', 'TYPE': 'Bridge', 'ONBOOT': 'no'}, 'bridged': True, 'ipv6addrs': ['fe80::210:18ff:fecd:daac/64'], 'gateway': '', 'bootproto4': 'none', 'netmask': '', 'stp': 'off', 'ipv4addrs': [], 'mtu': '9000', 'ipv6gateway': '::', 'ports': ['bond1.100']}, 'storage': {'iface': u'bond1', 'addr': '10.10.10.6', 'bridged': False, 'ipv6addrs': ['fe80::210:18ff:fecd:daac/64'], 'mtu': '9000', 'bootproto4': 'none', 'netmask': '255.255.255.0', 'ipv4addrs': ['10.10.10.6/24'], 'interface': u'bond1', 'ipv6gateway': '::', 'gateway': ''}, 'VMNetwork': {'iface': 'VMNetwork', 'addr': '', 'cfg': {'DEFROUTE': 'no', 'HOTPLUG': 'no', 'MTU': '1500', 'DELAY': '0', 'NM_CONTROLLED': 'no', 'BOOTPROTO': 'none', 'STP': 'off', 'DEVICE': 'VMNetwork', 'TYPE': 'Bridge', 'ONBOOT': 'no'}, 'bridged': True, 'ipv6addrs': ['fe80::62eb:69ff:fe20:b46c/64'], 'gateway': '', 'bootproto4': 'none', 'netmask': '', 'stp': 'off', 'ipv4addrs': [], 'mtu': '1500', 'ipv6gateway': '::', 'ports': ['bond0.36']}}, 'bridges': {'Internal': {'addr': '', 'cfg': {'DEFROUTE': 'no', 'HOTPLUG': 'no', 'MTU': '9000', 'DELAY': '0', 'NM_CONTROLLED': 'no', 'BOOTPROTO': 'none', 'STP': 'off', 'DEVICE': 'Internal', 'TYPE': 'Bridge', 'ONBOOT': 'no'}, 'ipv6addrs': ['fe80::210:18ff:fecd:daac/64'], 'mtu': '9000', 'netmask': '', 'stp': 'off', 'ipv4addrs': [], 'ipv6gateway': '::', 'gateway': '', 'opts': {'topology_change_detected': '0', 'multicast_last_member_count': '2', 'hash_elasticity': '4', 'multicast_query_response_interval': '999', 'multicast_snooping': '1', 'multicast_startup_query_interval': '3124', 'hello_timer': '100', 'multicast_querier_interval': '25496', 'max_age': '1999', 'hash_max': '512', 'stp_state': '0', 'root_id': '8000.001018cddaac', 'priority': '32768', 'multicast_membership_interval': '25996', 'root_path_cost': '0', 'root_port': '0', 'multicast_querier': '0', 'multicast_startup_query_count': '2', 'hello_time': '199', 'topology_change': '0', 'bridge_id': '8000.001018cddaac', 'topology_change_timer': '0', 'ageing_time': '29995', 'gc_timer': '0', 'group_addr': '1:80:c2:0:0:0', 'tcn_timer': '0', 'multicast_query_interval': '12498', 'multicast_last_member_interval': '99', 'multicast_router': '1', 'forward_delay': '0'}, 'ports': ['bond1.100']}, 'VMNetwork': {'addr': '', 'cfg': {'DEFROUTE': 'no', 'HOTPLUG': 'no', 'MTU': '1500', 'DELAY': '0', 'NM_CONTROLLED': 'no', 'BOOTPROTO': 'none', 'STP': 'off', 'DEVICE': 'VMNetwork', 'TYPE': 'Bridge', 'ONBOOT': 'no'}, 'ipv6addrs': ['fe80::62eb:69ff:fe20:b46c/64'], 'mtu': '1500', 'netmask': '', 'stp': 'off', 'ipv4addrs': [], 'ipv6gateway': '::', 'gateway': '', 'opts': {'topology_change_detected': '0', 'multicast_last_member_count': '2', 'hash_elasticity': '4', 'multicast_query_response_interval': '999', 'multicast_snooping': '1', 'multicast_startup_query_interval': '3124', 'hello_timer': '198', 'multicast_querier_interval': '25496', 'max_age': '1999', 'hash_max': '512', 'stp_state': '0', 'root_id': '8000.60eb6920b46c', 'priority': '32768', 'multicast_membership_interval': '25996', 'root_path_cost': '0', 'root_port': '0', 'multicast_querier': '0', 'multicast_startup_query_count': '2', 'hello_time': '199', 'topology_change': '0', 'bridge_id': '8000.60eb6920b46c', 'topology_change_timer': '0', 'ageing_time': '29995', 'gc_timer': '98', 'group_addr': '1:80:c2:0:0:0', 'tcn_timer': '0', 'multicast_query_interval': '12498', 'multicast_last_member_interval': '99', 'multicast_router': '1', 'forward_delay': '0'}, 'ports': ['bond0.36']}}, 'uuid': '44454C4C-4C00-1057-8053-B7C04F504E31', 'lastClientIface': 'bond1', 'nics': {'eth3': {'permhwaddr': '00:10:18:cd:da:ae', 'addr': '', 'cfg': {'SLAVE': 'yes', 'NM_CONTROLLED': 'no', 'MTU': '9000', 'HWADDR': '00:10:18:cd:da:ae', 'MASTER': 'bond1', 'DEVICE': 'eth3', 'ONBOOT': 'no'}, 'ipv6addrs': [], 'mtu': '9000', 'netmask': '', 'ipv4addrs': [], 'hwaddr': '00:10:18:cd:da:ac', 'speed': 1000}, 'eth2': {'permhwaddr': '00:10:18:cd:da:ac', 'addr': '', 'cfg': {'SLAVE': 'yes', 'NM_CONTROLLED': 'no', 'MTU': '9000', 'HWADDR': '00:10:18:cd:da:ac', 'MASTER': 'bond1', 'DEVICE': 'eth2', 'ONBOOT': 'no'}, 'ipv6addrs': [], 'mtu': '9000', 'netmask': '', 'ipv4addrs': [], 'hwaddr': '00:10:18:cd:da:ac', 'speed': 1000}, 'eth1': {'permhwaddr': '60:eb:69:20:b4:6d', 'addr': '', 'cfg': {'SLAVE': 'yes', 'NM_CONTROLLED': 'no', 'MTU': '1500', 'HWADDR': '60:eb:69:20:b4:6d', 'MASTER': 'bond0', 'DEVICE': 'eth1', 'ONBOOT': 'yes'}, 'ipv6addrs': [], 'mtu': '1500', 'netmask': '', 'ipv4addrs': [], 'hwaddr': '60:eb:69:20:b4:6c', 'speed': 1000}, 'eth0': {'permhwaddr': '60:eb:69:20:b4:6c', 'addr': '', 'cfg': {'SLAVE': 'yes', 'NM_CONTROLLED': 'no', 'MTU': '1500', 'HWADDR': '60:eb:69:20:b4:6c', 'MASTER': 'bond0', 'DEVICE': 'eth0', 'ONBOOT': 'yes'}, 'ipv6addrs': [], 'mtu': '1500', 'netmask': '', 'ipv4addrs': [], 'hwaddr': '60:eb:69:20:b4:6c', 'speed': 1000}}, 'software_revision': '1', 'clusterLevels': ['3.0', '3.1', '3.2', '3.3', '3.4', '3.5'], 'cpuFlags': u'fpu,vme,de,pse,tsc,msr,pae,mce,cx8,apic,sep,mtrr,pge,mca,cmov,pat,pse36,clflush,dts,acpi,mmx,fxsr,sse,sse2,ss,ht,tm,pbe,syscall,nx,pdpe1gb,rdtscp,lm,constant_tsc,arch_perfmon,pebs,bts,rep_good,xtopology,nonstop_tsc,pni,pclmulqdq,dtes64,monitor,ds_cpl,vmx,smx,est,tm2,ssse3,cx16,xtpr,pdcm,pcid,dca,sse4_1,sse4_2,popcnt,aes,lahf_lm,tpr_shadow,vnmi,flexpriority,ept,vpid,model_Nehalem,model_Conroe,model_coreduo,model_core2duo,model_Penryn,model_Westmere,model_n270', 'ISCSIInitiatorName': 'iqn.1994-05.com.redhat:32151ce183c8', 'netConfigDirty': 'False', 'supportedENGINEs': ['3.0', '3.1', '3.2', '3.3', '3.4', '3.5'], 'autoNumaBalancing': 2, 'reservedMem': '321', 'bondings': {'bond4': {'addr': '', 'cfg': {}, 'mtu': '1500', 'netmask': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00'}, 'bond0': {'addr': '', 'cfg': {'HOTPLUG': 'no', 'MTU': '1500', 'NM_CONTROLLED': 'no', 'BONDING_OPTS': 'mode=4 miimon=100', 'DEVICE': 'bond0', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::62eb:69ff:fe20:b46c/64'], 'mtu': '1500', 'netmask': '', 'ipv4addrs': [], 'hwaddr': '60:eb:69:20:b4:6c', 'slaves': ['eth0', 'eth1'], 'opts': {'miimon': '100', 'mode': '4'}}, 'bond1': {'addr': '10.10.10.6', 'cfg': {'DEFROUTE': 'no', 'IPADDR': '10.10.10.6', 'HOTPLUG': 'no', 'MTU': '9000', 'NM_CONTROLLED': 'no', 'NETMASK': '255.255.255.0', 'BOOTPROTO': 'none', 'BONDING_OPTS': 'mode=4 miimon=100', 'DEVICE': 'bond1', 'ONBOOT': 'no'}, 'ipv6addrs': ['fe80::210:18ff:fecd:daac/64'], 'mtu': '9000', 'netmask': '255.255.255.0', 'ipv4addrs': ['10.10.10.6/24'], 'hwaddr': '00:10:18:cd:da:ac', 'slaves': ['eth2', 'eth3'], 'opts': {'miimon': '100', 'mode': '4'}}, 'bond2': {'addr': '', 'cfg': {}, 'mtu': '1500', 'netmask': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00'}, 'bond3': {'addr': '', 'cfg': {}, 'mtu': '1500', 'netmask': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00'}}, 'software_version': '4.16', 'memSize': '24019', 'cpuSpeed': '2667.000', 'numaNodes': {u'1': {'totalMemory': '12288', 'cpus': [6, 7, 8, 9, 10, 11, 18, 19, 20, 21, 22, 23]}, u'0': {'totalMemory': '12278', 'cpus': [0, 1, 2, 3, 4, 5, 12, 13, 14, 15, 16, 17]}}, 'version_name': 'Snow Man', 'vlans': {'bond0.10': {'iface': 'bond0', 'addr': '43.252.176.16', 'cfg': {'DEFROUTE': 'yes', 'VLAN': 'yes', 'IPADDR': '43.252.176.16', 'HOTPLUG': 'no', 'GATEWAY': '43.252.176.1', 'NM_CONTROLLED': 'no', 'NETMASK': '255.255.255.0', 'BOOTPROTO': 'none', 'DEVICE': 'bond0.10', 'MTU': '1500', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::62eb:69ff:fe20:b46c/64'], 'vlanid': 10, 'mtu': '1500', 'netmask': '255.255.255.0', 'ipv4addrs': ['43.252.176.16/24']}, 'bond0.36': {'iface': 'bond0', 'addr': '', 'cfg': {'BRIDGE': 'VMNetwork', 'VLAN': 'yes', 'HOTPLUG': 'no', 'MTU': '1500', 'NM_CONTROLLED': 'no', 'DEVICE': 'bond0.36', 'ONBOOT': 'no'}, 'ipv6addrs': ['fe80::62eb:69ff:fe20:b46c/64'], 'vlanid': 36, 'mtu': '1500', 'netmask': '', 'ipv4addrs': []}, 'bond1.100': {'iface': 'bond1', 'addr': '', 'cfg': {'BRIDGE': 'Internal', 'VLAN': 'yes', 'HOTPLUG': 'no', 'MTU': '9000', 'NM_CONTROLLED': 'no', 'DEVICE': 'bond1.100', 'ONBOOT': 'no'}, 'ipv6addrs': ['fe80::210:18ff:fecd:daac/64'], 'vlanid': 100, 'mtu': '9000', 'netmask': '', 'ipv4addrs': []}}, 'cpuCores': '12', 'kvmEnabled': 'true', 'guestOverhead': '65', 'cpuThreads': '24', 'emulatedMachines': [u'rhel6.5.0', u'pc', u'rhel6.4.0', u'rhel6.3.0', u'rhel6.2.0', u'rhel6.1.0', u'rhel6.0.0', u'rhel5.5.0', u'rhel5.4.4', u'rhel5.4.0'], 'operatingSystem': {'release': '5.el6.centos.11.1', 'version': '6', 'name': 'RHEL'}, 'lastClient': '10.10.10.2'}} Thread-13::DEBUG::2014-11-25 14:55:36,860::BindingXMLRPC::1132::vds::(wrapper) client [10.10.10.2]::call getHardwareInfo with () {} flowID [5279acc6] Thread-13::DEBUG::2014-11-25 14:55:36,867::BindingXMLRPC::1139::vds::(wrapper) return getHardwareInfo with {'status': {'message': 'Done', 'code': 0}, 'info': {'systemProductName': 'CS24-TY', 'systemSerialNumber': '7LWSPN1', 'systemFamily': 'Server', 'systemVersion': 'A00', 'systemUUID': '44454c4c-4c00-1057-8053-b7c04f504e31', 'systemManufacturer': 'Dell'}} Thread-13::DEBUG::2014-11-25 14:55:36,968::BindingXMLRPC::1132::vds::(wrapper) client [10.10.10.2]::call hostsList with () {} flowID [39d35dd7] Thread-13::DEBUG::2014-11-25 14:55:37,022::BindingXMLRPC::1139::vds::(wrapper) return hostsList with {'status': {'message': 'Done', 'code': 0}, 'hosts': [{'status': 'CONNECTED', 'hostname': '10.10.10.6', 'uuid': '918cef1f-ed83-4570-90ad-39c5ceec753c'}, {'status': 'CONNECTED', 'hostname': 'compute5.3linux.com', 'uuid': '268139cb-e7b7-48e9-99cf-e26c523516e7'}, {'status': 'CONNECTED', 'hostname': 'compute1.3linux.com', 'uuid': '69b19f4e-03c8-4fe1-a644-2701c41d7020'}, {'status': 'CONNECTED', 'hostname': 'compute2.3linux.com', 'uuid': '2cf3428c-62be-42f4-86d3-ef67e7dfc97f'}, {'status': 'CONNECTED', 'hostname': 'compute3.3linux.com', 'uuid': '0d94d896-e994-4deb-b1a1-d6f68be86c30'}]} Thread-13::DEBUG::2014-11-25 14:55:37,106::BindingXMLRPC::318::vds::(wrapper) client [10.10.10.2] flowID [5d2c0061] Thread-13::DEBUG::2014-11-25 14:55:37,107::task::595::Storage.TaskManager.Task::(_updateState) Task=`1a590712-cbec-4cdf-b34c-96578c07f282`::moving from state init -> state preparing Thread-13::INFO::2014-11-25 14:55:37,107::logUtils::44::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=1, spUUID='f4966810-0923-4752-a054-2b4954584970', conList=[{'connection': '43.252.176.12:/var/lib/exports/iso', 'iqn': '', 'user': '', 'tpgt': '1', 'password': '******', 'id': 'df63624e-7605-4ee7-8262-f2023461baaa', 'port': ''}], options=None) Thread-13::DEBUG::2014-11-25 14:55:37,109::fileUtils::142::Storage.fileUtils::(createdir) Creating directory: /rhev/data-center/mnt/43.252.176.12:_var_lib_exports_iso Thread-13::WARNING::2014-11-25 14:55:37,110::fileUtils::149::Storage.fileUtils::(createdir) Dir /rhev/data-center/mnt/43.252.176.12:_var_lib_exports_iso already exists Thread-13::DEBUG::2014-11-25 14:55:37,110::mount::227::Storage.Misc.excCmd::(_runcmd) /usr/bin/sudo -n /bin/mount -t nfs -o soft,nosharecache,timeo=600,retrans=6,nfsvers=3 43.252.176.12:/var/lib/exports/iso /rhev/data-center/mnt/43.252.176.12:_var_lib_exports_iso (cwd None) Thread-13::DEBUG::2014-11-25 14:55:37,376::__init__::159::IOProcessClient::(_run) Starting IOProcess... Thread-14::DEBUG::2014-11-25 14:55:37,399::__init__::232::IOProcess::(_processLogs) Opening communication channels... Thread-14::DEBUG::2014-11-25 14:55:37,400::__init__::232::IOProcess::(_processLogs) Receiving request... Thread-14::DEBUG::2014-11-25 14:55:37,400::__init__::232::IOProcess::(_processLogs) Queuing request in the thread pool... Thread-14::DEBUG::2014-11-25 14:55:37,400::__init__::232::IOProcess::(_processLogs) Extracting request information... Thread-14::DEBUG::2014-11-25 14:55:37,400::__init__::232::IOProcess::(_processLogs) (1) Got request for method 'access' Thread-14::DEBUG::2014-11-25 14:55:37,402::__init__::232::IOProcess::(_processLogs) (1) Queuing response Thread-13::DEBUG::2014-11-25 14:55:37,417::hsm::2372::Storage.HSM::(__prefetchDomains) nfs local path: /rhev/data-center/mnt/43.252.176.12:_var_lib_exports_iso Thread-14::DEBUG::2014-11-25 14:55:37,417::__init__::232::IOProcess::(_processLogs) Receiving request... Thread-14::DEBUG::2014-11-25 14:55:37,418::__init__::232::IOProcess::(_processLogs) Queuing request in the thread pool... Thread-14::DEBUG::2014-11-25 14:55:37,418::__init__::232::IOProcess::(_processLogs) Extracting request information... Thread-14::DEBUG::2014-11-25 14:55:37,418::__init__::232::IOProcess::(_processLogs) (2) Got request for method 'glob' Thread-14::DEBUG::2014-11-25 14:55:37,418::__init__::232::IOProcess::(_processLogs) (2) Queuing response Thread-13::DEBUG::2014-11-25 14:55:37,418::hsm::2396::Storage.HSM::(__prefetchDomains) Found SD uuids: (u'9b2fdce9-a795-44a7-86ed-99e514d24399',) Thread-13::DEBUG::2014-11-25 14:55:37,419::hsm::2452::Storage.HSM::(connectStorageServer) knownSDs: {9b2fdce9-a795-44a7-86ed-99e514d24399: storage.nfsSD.findDomain} Thread-13::INFO::2014-11-25 14:55:37,419::logUtils::47::dispatcher::(wrapper) Run and protect: connectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': 'df63624e-7605-4ee7-8262-f2023461baaa'}]} Thread-13::DEBUG::2014-11-25 14:55:37,419::task::1191::Storage.TaskManager.Task::(prepare) Task=`1a590712-cbec-4cdf-b34c-96578c07f282`::finished: {'statuslist': [{'status': 0, 'id': 'df63624e-7605-4ee7-8262-f2023461baaa'}]} Thread-13::DEBUG::2014-11-25 14:55:37,419::task::595::Storage.TaskManager.Task::(_updateState) Task=`1a590712-cbec-4cdf-b34c-96578c07f282`::moving from state preparing -> state finished Thread-13::DEBUG::2014-11-25 14:55:37,419::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-13::DEBUG::2014-11-25 14:55:37,420::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-13::DEBUG::2014-11-25 14:55:37,420::task::993::Storage.TaskManager.Task::(_decref) Task=`1a590712-cbec-4cdf-b34c-96578c07f282`::ref 0 aborting False Thread-13::DEBUG::2014-11-25 14:55:37,481::BindingXMLRPC::318::vds::(wrapper) client [10.10.10.2] flowID [5d2c0061] Thread-13::DEBUG::2014-11-25 14:55:37,481::task::595::Storage.TaskManager.Task::(_updateState) Task=`1c9c3722-aeef-41da-a695-80939cb4be9f`::moving from state init -> state preparing Thread-13::INFO::2014-11-25 14:55:37,482::logUtils::44::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=7, spUUID='f4966810-0923-4752-a054-2b4954584970', conList=[{'port': '', 'connection': '10.10.10.3:/data1', 'iqn': '', 'user': '', 'tpgt': '1', 'vfs_type': 'glusterfs', 'password': '******', 'id': '5fb19bf8-41a3-4f8d-9177-12d68e963624'}], options=None) Thread-13::DEBUG::2014-11-25 14:55:37,483::fileUtils::142::Storage.fileUtils::(createdir) Creating directory: /rhev/data-center/mnt/glusterSD/10.10.10.3:_data1 Thread-13::WARNING::2014-11-25 14:55:37,516::fileUtils::149::Storage.fileUtils::(createdir) Dir /rhev/data-center/mnt/glusterSD/10.10.10.3:_data1 already exists Thread-13::DEBUG::2014-11-25 14:55:37,516::mount::227::Storage.Misc.excCmd::(_runcmd) /usr/bin/sudo -n /bin/mount -t glusterfs 10.10.10.3:/data1 /rhev/data-center/mnt/glusterSD/10.10.10.3:_data1 (cwd None) Thread-14::DEBUG::2014-11-25 14:55:37,776::__init__::232::IOProcess::(_processLogs) Receiving request... Thread-14::DEBUG::2014-11-25 14:55:37,782::__init__::232::IOProcess::(_processLogs) Queuing request in the thread pool... Thread-14::DEBUG::2014-11-25 14:55:37,782::__init__::232::IOProcess::(_processLogs) Extracting request information... Thread-14::DEBUG::2014-11-25 14:55:37,783::__init__::232::IOProcess::(_processLogs) (3) Got request for method 'access' Thread-14::DEBUG::2014-11-25 14:55:37,783::__init__::232::IOProcess::(_processLogs) (3) Queuing response Thread-13::DEBUG::2014-11-25 14:55:37,792::hsm::2384::Storage.HSM::(__prefetchDomains) glusterDomPath: glusterSD/* Thread-14::DEBUG::2014-11-25 14:55:37,793::__init__::232::IOProcess::(_processLogs) Receiving request... Thread-14::DEBUG::2014-11-25 14:55:37,794::__init__::232::IOProcess::(_processLogs) Queuing request in the thread pool... Thread-14::DEBUG::2014-11-25 14:55:37,794::__init__::232::IOProcess::(_processLogs) Extracting request information... Thread-14::DEBUG::2014-11-25 14:55:37,794::__init__::232::IOProcess::(_processLogs) (4) Got request for method 'glob' Thread-14::DEBUG::2014-11-25 14:55:37,808::__init__::232::IOProcess::(_processLogs) (4) Queuing response Thread-13::DEBUG::2014-11-25 14:55:37,809::hsm::2396::Storage.HSM::(__prefetchDomains) Found SD uuids: (u'ea499cc0-684f-4a2f-abef-43ff28d649cb',) Thread-13::DEBUG::2014-11-25 14:55:37,809::hsm::2452::Storage.HSM::(connectStorageServer) knownSDs: {9b2fdce9-a795-44a7-86ed-99e514d24399: storage.nfsSD.findDomain, ea499cc0-684f-4a2f-abef-43ff28d649cb: storage.glusterSD.findDomain} Thread-13::INFO::2014-11-25 14:55:37,809::logUtils::47::dispatcher::(wrapper) Run and protect: connectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': '5fb19bf8-41a3-4f8d-9177-12d68e963624'}]} Thread-13::DEBUG::2014-11-25 14:55:37,810::task::1191::Storage.TaskManager.Task::(prepare) Task=`1c9c3722-aeef-41da-a695-80939cb4be9f`::finished: {'statuslist': [{'status': 0, 'id': '5fb19bf8-41a3-4f8d-9177-12d68e963624'}]} Thread-13::DEBUG::2014-11-25 14:55:37,810::task::595::Storage.TaskManager.Task::(_updateState) Task=`1c9c3722-aeef-41da-a695-80939cb4be9f`::moving from state preparing -> state finished Thread-13::DEBUG::2014-11-25 14:55:37,810::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-13::DEBUG::2014-11-25 14:55:37,810::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-13::DEBUG::2014-11-25 14:55:37,810::task::993::Storage.TaskManager.Task::(_decref) Task=`1c9c3722-aeef-41da-a695-80939cb4be9f`::ref 0 aborting False Thread-13::DEBUG::2014-11-25 14:55:37,876::BindingXMLRPC::318::vds::(wrapper) client [10.10.10.2] Thread-13::DEBUG::2014-11-25 14:55:37,876::task::595::Storage.TaskManager.Task::(_updateState) Task=`0bbd8080-ab4c-49a2-9708-49e6e5bd0b78`::moving from state init -> state preparing Thread-13::INFO::2014-11-25 14:55:37,877::logUtils::44::dispatcher::(wrapper) Run and protect: connectStoragePool(spUUID='f4966810-0923-4752-a054-2b4954584970', hostID=1, msdUUID='ea499cc0-684f-4a2f-abef-43ff28d649cb', masterVersion=1, domainsMap={'9b2fdce9-a795-44a7-86ed-99e514d24399': 'active', 'ea499cc0-684f-4a2f-abef-43ff28d649cb': 'active'}, options=None) Thread-13::DEBUG::2014-11-25 14:55:37,877::resourceManager::198::Storage.ResourceManager.Request::(__init__) ResName=`Storage.HsmDomainMonitorLock`ReqID=`bf59d66b-9c39-45c7-9009-497bffabb81e`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '1011' at 'connectStoragePool' Thread-13::DEBUG::2014-11-25 14:55:37,877::resourceManager::542::Storage.ResourceManager::(registerResource) Trying to register resource 'Storage.HsmDomainMonitorLock' for lock type 'exclusive' Thread-13::DEBUG::2014-11-25 14:55:37,877::resourceManager::601::Storage.ResourceManager::(registerResource) Resource 'Storage.HsmDomainMonitorLock' is free. Now locking as 'exclusive' (1 active user) Thread-13::DEBUG::2014-11-25 14:55:37,878::resourceManager::238::Storage.ResourceManager.Request::(grant) ResName=`Storage.HsmDomainMonitorLock`ReqID=`bf59d66b-9c39-45c7-9009-497bffabb81e`::Granted request Thread-13::DEBUG::2014-11-25 14:55:37,878::resourceManager::198::Storage.ResourceManager.Request::(__init__) ResName=`Storage.f4966810-0923-4752-a054-2b4954584970`ReqID=`dee61c09-c6aa-4bae-aeba-8f628da900c5`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '1059' at '_connectStoragePool' Thread-13::DEBUG::2014-11-25 14:55:37,878::resourceManager::542::Storage.ResourceManager::(registerResource) Trying to register resource 'Storage.f4966810-0923-4752-a054-2b4954584970' for lock type 'exclusive' Thread-13::DEBUG::2014-11-25 14:55:37,878::resourceManager::601::Storage.ResourceManager::(registerResource) Resource 'Storage.f4966810-0923-4752-a054-2b4954584970' is free. Now locking as 'exclusive' (1 active user) Thread-13::DEBUG::2014-11-25 14:55:37,879::resourceManager::238::Storage.ResourceManager.Request::(grant) ResName=`Storage.f4966810-0923-4752-a054-2b4954584970`ReqID=`dee61c09-c6aa-4bae-aeba-8f628da900c5`::Granted request Thread-13::DEBUG::2014-11-25 14:55:37,880::spbackends::485::Storage.StoragePoolMemoryBackend::(updateVersionAndDomains) updating domain version to 1 and domains map to {'9b2fdce9-a795-44a7-86ed-99e514d24399': 'active', 'ea499cc0-684f-4a2f-abef-43ff28d649cb': 'active'} Thread-13::INFO::2014-11-25 14:55:37,880::spbackends::433::Storage.StoragePoolMemoryBackend::(setDomainsMap) new storage pool master version 1 and domains map {'9b2fdce9-a795-44a7-86ed-99e514d24399': 'Active', 'ea499cc0-684f-4a2f-abef-43ff28d649cb': 'Active'} Thread-13::INFO::2014-11-25 14:55:37,880::sp::133::Storage.StoragePool::(setBackend) updating pool f4966810-0923-4752-a054-2b4954584970 backend from type NoneType instance 0x33bbd72210 to type StoragePoolMemoryBackend instance 0x7f43d0055158 Thread-13::INFO::2014-11-25 14:55:37,880::sp::631::Storage.StoragePool::(connect) Connect host #1 to the storage pool f4966810-0923-4752-a054-2b4954584970 with master domain: ea499cc0-684f-4a2f-abef-43ff28d649cb (ver = 1) Thread-13::DEBUG::2014-11-25 14:55:37,880::lvm::489::Storage.OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex Thread-13::DEBUG::2014-11-25 14:55:37,881::lvm::491::Storage.OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex Thread-13::DEBUG::2014-11-25 14:55:37,881::lvm::500::Storage.OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex Thread-13::DEBUG::2014-11-25 14:55:37,881::lvm::502::Storage.OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex Thread-13::DEBUG::2014-11-25 14:55:37,881::lvm::520::Storage.OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex Thread-13::DEBUG::2014-11-25 14:55:37,881::lvm::522::Storage.OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex Thread-13::DEBUG::2014-11-25 14:55:37,882::misc::741::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage) Thread-13::DEBUG::2014-11-25 14:55:37,882::misc::743::Storage.SamplingMethod::(__call__) Got in to sampling method Thread-13::DEBUG::2014-11-25 14:55:37,882::misc::741::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan) Thread-13::DEBUG::2014-11-25 14:55:37,882::misc::743::Storage.SamplingMethod::(__call__) Got in to sampling method Thread-13::DEBUG::2014-11-25 14:55:37,882::iscsi::403::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds Thread-13::DEBUG::2014-11-25 14:55:37,882::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) /usr/bin/sudo -n /sbin/iscsiadm -m session -R (cwd None) Thread-13::DEBUG::2014-11-25 14:55:37,894::misc::751::Storage.SamplingMethod::(__call__) Returning last result Thread-13::DEBUG::2014-11-25 14:55:37,896::multipath::110::Storage.Misc.excCmd::(rescan) /usr/bin/sudo -n /sbin/multipath (cwd None) Thread-13::DEBUG::2014-11-25 14:55:37,981::multipath::110::Storage.Misc.excCmd::(rescan) SUCCESS: = ''; = 0 Thread-13::DEBUG::2014-11-25 14:55:37,983::lvm::489::Storage.OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex Thread-13::DEBUG::2014-11-25 14:55:37,983::lvm::491::Storage.OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex Thread-13::DEBUG::2014-11-25 14:55:37,983::lvm::500::Storage.OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex Thread-13::DEBUG::2014-11-25 14:55:37,984::lvm::502::Storage.OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex Thread-13::DEBUG::2014-11-25 14:55:37,984::lvm::520::Storage.OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex Thread-13::DEBUG::2014-11-25 14:55:37,984::lvm::522::Storage.OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex Thread-13::DEBUG::2014-11-25 14:55:37,984::misc::751::Storage.SamplingMethod::(__call__) Returning last result Thread-14::DEBUG::2014-11-25 14:55:37,986::__init__::232::IOProcess::(_processLogs) Receiving request... Thread-14::DEBUG::2014-11-25 14:55:37,986::__init__::232::IOProcess::(_processLogs) Queuing request in the thread pool... Thread-14::DEBUG::2014-11-25 14:55:37,986::__init__::232::IOProcess::(_processLogs) Extracting request information... Thread-14::DEBUG::2014-11-25 14:55:37,986::__init__::232::IOProcess::(_processLogs) (5) Got request for method 'glob' Thread-14::DEBUG::2014-11-25 14:55:37,997::__init__::232::IOProcess::(_processLogs) (5) Queuing response Thread-13::DEBUG::2014-11-25 14:55:37,999::fileSD::152::Storage.StorageDomain::(__init__) Reading domain in path /rhev/data-center/mnt/glusterSD/10.10.10.3:_data1/ea499cc0-684f-4a2f-abef-43ff28d649cb Thread-14::DEBUG::2014-11-25 14:55:38,000::__init__::232::IOProcess::(_processLogs) Receiving request... Thread-14::DEBUG::2014-11-25 14:55:38,000::__init__::232::IOProcess::(_processLogs) Queuing request in the thread pool... Thread-14::DEBUG::2014-11-25 14:55:38,000::__init__::232::IOProcess::(_processLogs) Extracting request information... Thread-14::DEBUG::2014-11-25 14:55:38,000::__init__::232::IOProcess::(_processLogs) (6) Got request for method 'touch' Thread-14::DEBUG::2014-11-25 14:55:38,002::__init__::232::IOProcess::(_processLogs) (6) Queuing response Thread-13::DEBUG::2014-11-25 14:55:38,002::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with FileMetadataRW backend Thread-14::DEBUG::2014-11-25 14:55:38,003::__init__::232::IOProcess::(_processLogs) Receiving request... Thread-14::DEBUG::2014-11-25 14:55:38,003::__init__::232::IOProcess::(_processLogs) Queuing request in the thread pool... Thread-14::DEBUG::2014-11-25 14:55:38,004::__init__::232::IOProcess::(_processLogs) Extracting request information... Thread-14::DEBUG::2014-11-25 14:55:38,004::__init__::232::IOProcess::(_processLogs) (7) Got request for method 'readfile' Thread-14::DEBUG::2014-11-25 14:55:38,018::__init__::232::IOProcess::(_processLogs) (7) Queuing response Thread-13::DEBUG::2014-11-25 14:55:38,019::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=data', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=SV_WTC', 'POOL_DOMAINS=9b2fdce9-a795-44a7-86ed-99e514d24399:Active,ea499cc0-684f-4a2f-abef-43ff28d649cb:Active,4b7c7f94-2cee-4fdc-9153-c2f8cd1f7c6b:Active', 'POOL_SPM_ID=4', 'POOL_SPM_LVER=6', 'POOL_UUID=f4966810-0923-4752-a054-2b4954584970', 'REMOTE_PATH=10.10.10.3:/data1', 'ROLE=Master', 'SDUUID=ea499cc0-684f-4a2f-abef-43ff28d649cb', 'TYPE=GLUSTERFS', 'VERSION=3', '_SHA_CKSUM=45470801303345e61389c0718708ed07c20ebe23'] Thread-14::DEBUG::2014-11-25 14:55:38,019::__init__::232::IOProcess::(_processLogs) Receiving request... Thread-14::DEBUG::2014-11-25 14:55:38,020::__init__::232::IOProcess::(_processLogs) Queuing request in the thread pool... Thread-14::DEBUG::2014-11-25 14:55:38,020::__init__::232::IOProcess::(_processLogs) Extracting request information... Thread-14::DEBUG::2014-11-25 14:55:38,020::__init__::232::IOProcess::(_processLogs) (8) Got request for method 'access' Thread-14::DEBUG::2014-11-25 14:55:38,020::__init__::232::IOProcess::(_processLogs) (8) Queuing response Thread-14::DEBUG::2014-11-25 14:55:38,021::__init__::232::IOProcess::(_processLogs) Receiving request... Thread-14::DEBUG::2014-11-25 14:55:38,021::__init__::232::IOProcess::(_processLogs) Queuing request in the thread pool... Thread-14::DEBUG::2014-11-25 14:55:38,021::__init__::232::IOProcess::(_processLogs) Extracting request information... Thread-14::DEBUG::2014-11-25 14:55:38,021::__init__::232::IOProcess::(_processLogs) (9) Got request for method 'glob' Thread-14::DEBUG::2014-11-25 14:55:38,032::__init__::232::IOProcess::(_processLogs) (9) Queuing response Thread-13::DEBUG::2014-11-25 14:55:38,033::fileSD::610::Storage.StorageDomain::(imageGarbageCollector) Removing remnants of deleted images [] Thread-13::DEBUG::2014-11-25 14:55:38,033::resourceManager::421::Storage.ResourceManager::(registerNamespace) Registering namespace 'ea499cc0-684f-4a2f-abef-43ff28d649cb_imageNS' Thread-13::DEBUG::2014-11-25 14:55:38,033::resourceManager::421::Storage.ResourceManager::(registerNamespace) Registering namespace 'ea499cc0-684f-4a2f-abef-43ff28d649cb_volumeNS' Thread-13::DEBUG::2014-11-25 14:55:38,034::sp::1390::Storage.StoragePool::(setMasterDomain) Master domain ea499cc0-684f-4a2f-abef-43ff28d649cb verified, version 1 Thread-13::DEBUG::2014-11-25 14:55:38,034::misc::741::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.sp.updateMonitoringThreads) Thread-13::DEBUG::2014-11-25 14:55:38,034::misc::743::Storage.SamplingMethod::(__call__) Got in to sampling method Thread-13::INFO::2014-11-25 14:55:38,034::domainMonitor::100::Storage.DomainMonitor::(startMonitoring) Start monitoring 9b2fdce9-a795-44a7-86ed-99e514d24399 Thread-13::DEBUG::2014-11-25 14:55:38,035::sp::1413::Storage.StoragePool::(updateMonitoringThreads) Storage Pool `f4966810-0923-4752-a054-2b4954584970` started monitoring domain `9b2fdce9-a795-44a7-86ed-99e514d24399` Thread-17::DEBUG::2014-11-25 14:55:38,035::domainMonitor::182::Storage.DomainMonitorThread::(_monitorLoop) Starting domain monitor for 9b2fdce9-a795-44a7-86ed-99e514d24399 Thread-13::INFO::2014-11-25 14:55:38,036::domainMonitor::100::Storage.DomainMonitor::(startMonitoring) Start monitoring ea499cc0-684f-4a2f-abef-43ff28d649cb Thread-18::DEBUG::2014-11-25 14:55:38,038::domainMonitor::182::Storage.DomainMonitorThread::(_monitorLoop) Starting domain monitor for ea499cc0-684f-4a2f-abef-43ff28d649cb Thread-13::DEBUG::2014-11-25 14:55:38,038::sp::1413::Storage.StoragePool::(updateMonitoringThreads) Storage Pool `f4966810-0923-4752-a054-2b4954584970` started monitoring domain `ea499cc0-684f-4a2f-abef-43ff28d649cb` Thread-13::DEBUG::2014-11-25 14:55:38,043::misc::751::Storage.SamplingMethod::(__call__) Returning last result Thread-13::DEBUG::2014-11-25 14:55:38,044::fileUtils::142::Storage.fileUtils::(createdir) Creating directory: /rhev/data-center/f4966810-0923-4752-a054-2b4954584970 Thread-14::DEBUG::2014-11-25 14:55:38,044::__init__::232::IOProcess::(_processLogs) Receiving request... Thread-13::WARNING::2014-11-25 14:55:38,045::fileUtils::149::Storage.fileUtils::(createdir) Dir /rhev/data-center/f4966810-0923-4752-a054-2b4954584970 already exists Thread-14::DEBUG::2014-11-25 14:55:38,045::__init__::232::IOProcess::(_processLogs) Queuing request in the thread pool... Thread-14::DEBUG::2014-11-25 14:55:38,046::__init__::232::IOProcess::(_processLogs) Extracting request information... Thread-14::DEBUG::2014-11-25 14:55:38,047::__init__::232::IOProcess::(_processLogs) (10) Got request for method 'glob' Thread-13::DEBUG::2014-11-25 14:55:38,048::lvm::365::Storage.OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex Thread-14::DEBUG::2014-11-25 14:55:38,049::__init__::232::IOProcess::(_processLogs) (10) Queuing response Thread-14::DEBUG::2014-11-25 14:55:38,051::__init__::232::IOProcess::(_processLogs) Receiving request... Thread-14::DEBUG::2014-11-25 14:55:38,053::__init__::232::IOProcess::(_processLogs) Queuing request in the thread pool... Thread-13::DEBUG::2014-11-25 14:55:38,054::lvm::288::Storage.Misc.excCmd::(cmd) /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 obtain_device_list_from_udev=0 filter = [ '\''a|/dev/mapper/brick7|/dev/mapper/brick8|'\'', '\''r|.*|'\'' ] } global { locking_type=1 prioritise_write_locks=1 wait_for_locks=1 use_lvmetad=0 } backup { retain_min = 50 retain_days = 0 } ' --noheadings --units b --nosuffix --separator '|' --ignoreskippedcluster -o uuid,name,attr,size,free,extent_size,extent_count,free_count,tags,vg_mda_size,vg_mda_free,lv_count,pv_count,pv_name 9b2fdce9-a795-44a7-86ed-99e514d24399 (cwd None) Thread-14::DEBUG::2014-11-25 14:55:38,056::__init__::232::IOProcess::(_processLogs) Extracting request information... Thread-14::DEBUG::2014-11-25 14:55:38,063::__init__::232::IOProcess::(_processLogs) (11) Got request for method 'glob' Thread-14::DEBUG::2014-11-25 14:55:38,064::__init__::232::IOProcess::(_processLogs) (11) Queuing response Thread-14::DEBUG::2014-11-25 14:55:38,067::__init__::232::IOProcess::(_processLogs) Receiving request... Thread-14::DEBUG::2014-11-25 14:55:38,069::__init__::232::IOProcess::(_processLogs) Queuing request in the thread pool... Thread-14::DEBUG::2014-11-25 14:55:38,070::__init__::232::IOProcess::(_processLogs) Extracting request information... Thread-17::DEBUG::2014-11-25 14:55:38,071::fileSD::152::Storage.StorageDomain::(__init__) Reading domain in path /rhev/data-center/mnt/43.252.176.12:_var_lib_exports_iso/9b2fdce9-a795-44a7-86ed-99e514d24399 Thread-14::DEBUG::2014-11-25 14:55:38,071::__init__::232::IOProcess::(_processLogs) (12) Got request for method 'statvfs' Thread-14::DEBUG::2014-11-25 14:55:38,073::__init__::232::IOProcess::(_processLogs) (12) Queuing response Thread-14::DEBUG::2014-11-25 14:55:38,074::__init__::232::IOProcess::(_processLogs) Receiving request... Thread-14::DEBUG::2014-11-25 14:55:38,075::__init__::232::IOProcess::(_processLogs) Queuing request in the thread pool... Thread-18::DEBUG::2014-11-25 14:55:38,075::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/glusterSD/10.10.10.3:_data1/ea499cc0-684f-4a2f-abef-43ff28d649cb/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None) Thread-14::DEBUG::2014-11-25 14:55:38,076::__init__::232::IOProcess::(_processLogs) Extracting request information... Thread-14::DEBUG::2014-11-25 14:55:38,082::__init__::232::IOProcess::(_processLogs) (13) Got request for method 'touch' Thread-18::DEBUG::2014-11-25 14:55:38,083::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: = '0+1 records in\n0+1 records out\n540 bytes (540 B) copied, 0.000480957 s, 1.1 MB/s\n'; = 0 Thread-14::DEBUG::2014-11-25 14:55:38,084::__init__::232::IOProcess::(_processLogs) (13) Queuing response Thread-17::DEBUG::2014-11-25 14:55:38,087::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with FileMetadataRW backend Thread-14::DEBUG::2014-11-25 14:55:38,088::__init__::232::IOProcess::(_processLogs) Receiving request... Thread-14::DEBUG::2014-11-25 14:55:38,089::__init__::232::IOProcess::(_processLogs) Queuing request in the thread pool... Thread-14::DEBUG::2014-11-25 14:55:38,089::__init__::232::IOProcess::(_processLogs) Extracting request information... Thread-14::DEBUG::2014-11-25 14:55:38,089::__init__::232::IOProcess::(_processLogs) (14) Got request for method 'statvfs' Thread-14::DEBUG::2014-11-25 14:55:38,089::__init__::232::IOProcess::(_processLogs) (14) Queuing response Thread-14::DEBUG::2014-11-25 14:55:38,090::__init__::232::IOProcess::(_processLogs) Receiving request... Thread-14::DEBUG::2014-11-25 14:55:38,091::__init__::232::IOProcess::(_processLogs) Queuing request in the thread pool... Thread-14::DEBUG::2014-11-25 14:55:38,091::__init__::232::IOProcess::(_processLogs) Extracting request information... Thread-14::DEBUG::2014-11-25 14:55:38,091::__init__::232::IOProcess::(_processLogs) (15) Got request for method 'readfile' Thread-14::DEBUG::2014-11-25 14:55:38,092::__init__::232::IOProcess::(_processLogs) (15) Queuing response Thread-17::DEBUG::2014-11-25 14:55:38,092::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Iso', 'DESCRIPTION=ISO_DOMAIN', 'IOOPTIMEOUTSEC=1', 'LEASERETRIES=3', 'LEASETIMESEC=5', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=0', 'POOL_UUID=00000002-0002-0002-0002-0000000003a1,9dadc868-d291-43fb-be72-ad4b1a5554f8,f4966810-0923-4752-a054-2b4954584970', 'REMOTE_PATH=cloud-mgmt.3linux.com:/var/lib/exports/iso', 'ROLE=Regular', 'SDUUID=9b2fdce9-a795-44a7-86ed-99e514d24399', 'TYPE=NFS', 'VERSION=0', '_SHA_CKSUM=e931f9ce795e9fbe179b80f741831be137b45fd6'] Thread-14::DEBUG::2014-11-25 14:55:38,093::__init__::232::IOProcess::(_processLogs) Receiving request... Thread-14::DEBUG::2014-11-25 14:55:38,094::__init__::232::IOProcess::(_processLogs) Queuing request in the thread pool... Thread-14::DEBUG::2014-11-25 14:55:38,095::__init__::232::IOProcess::(_processLogs) Extracting request information... Thread-14::DEBUG::2014-11-25 14:55:38,095::__init__::232::IOProcess::(_processLogs) (16) Got request for method 'access' Thread-14::DEBUG::2014-11-25 14:55:38,095::__init__::232::IOProcess::(_processLogs) (16) Queuing response Thread-14::DEBUG::2014-11-25 14:55:38,096::__init__::232::IOProcess::(_processLogs) Receiving request... Thread-14::DEBUG::2014-11-25 14:55:38,097::__init__::232::IOProcess::(_processLogs) Queuing request in the thread pool... Thread-14::DEBUG::2014-11-25 14:55:38,097::__init__::232::IOProcess::(_processLogs) Extracting request information... Thread-14::DEBUG::2014-11-25 14:55:38,097::__init__::232::IOProcess::(_processLogs) (17) Got request for method 'access' Thread-14::DEBUG::2014-11-25 14:55:38,097::__init__::232::IOProcess::(_processLogs) (17) Queuing response Thread-14::DEBUG::2014-11-25 14:55:38,098::__init__::232::IOProcess::(_processLogs) Receiving request... Thread-14::DEBUG::2014-11-25 14:55:38,098::__init__::232::IOProcess::(_processLogs) Queuing request in the thread pool... Thread-14::DEBUG::2014-11-25 14:55:38,098::__init__::232::IOProcess::(_processLogs) Extracting request information... Thread-14::DEBUG::2014-11-25 14:55:38,099::__init__::232::IOProcess::(_processLogs) (18) Got request for method 'access' Thread-14::DEBUG::2014-11-25 14:55:38,099::__init__::232::IOProcess::(_processLogs) (18) Queuing response Thread-14::DEBUG::2014-11-25 14:55:38,099::__init__::232::IOProcess::(_processLogs) Receiving request... Thread-14::DEBUG::2014-11-25 14:55:38,100::__init__::232::IOProcess::(_processLogs) Queuing request in the thread pool... Thread-14::DEBUG::2014-11-25 14:55:38,100::__init__::232::IOProcess::(_processLogs) Extracting request information... Thread-14::DEBUG::2014-11-25 14:55:38,100::__init__::232::IOProcess::(_processLogs) (19) Got request for method 'glob' Thread-14::DEBUG::2014-11-25 14:55:38,100::__init__::232::IOProcess::(_processLogs) (19) Queuing response Thread-17::DEBUG::2014-11-25 14:55:38,101::fileSD::610::Storage.StorageDomain::(imageGarbageCollector) Removing remnants of deleted images [] Thread-14::DEBUG::2014-11-25 14:55:38,101::__init__::232::IOProcess::(_processLogs) Receiving request... Thread-14::DEBUG::2014-11-25 14:55:38,103::__init__::232::IOProcess::(_processLogs) Queuing request in the thread pool... Thread-17::DEBUG::2014-11-25 14:55:38,103::resourceManager::421::Storage.ResourceManager::(registerNamespace) Registering namespace '9b2fdce9-a795-44a7-86ed-99e514d24399_imageNS' Thread-14::DEBUG::2014-11-25 14:55:38,104::__init__::232::IOProcess::(_processLogs) Extracting request information... Thread-17::DEBUG::2014-11-25 14:55:38,105::resourceManager::421::Storage.ResourceManager::(registerNamespace) Registering namespace '9b2fdce9-a795-44a7-86ed-99e514d24399_volumeNS' Thread-14::DEBUG::2014-11-25 14:55:38,105::__init__::232::IOProcess::(_processLogs) (20) Got request for method 'access' Thread-14::DEBUG::2014-11-25 14:55:38,107::__init__::232::IOProcess::(_processLogs) (20) Queuing response Thread-14::DEBUG::2014-11-25 14:55:38,108::__init__::232::IOProcess::(_processLogs) Receiving request... Thread-14::DEBUG::2014-11-25 14:55:38,108::__init__::232::IOProcess::(_processLogs) Queuing request in the thread pool... Thread-14::DEBUG::2014-11-25 14:55:38,109::__init__::232::IOProcess::(_processLogs) Extracting request information... Thread-14::DEBUG::2014-11-25 14:55:38,109::__init__::232::IOProcess::(_processLogs) (21) Got request for method 'statvfs' Thread-14::DEBUG::2014-11-25 14:55:38,109::__init__::232::IOProcess::(_processLogs) (21) Queuing response Thread-18::DEBUG::2014-11-25 14:55:38,111::domainMonitor::264::Storage.DomainMonitorThread::(_monitorDomain) Domain ea499cc0-684f-4a2f-abef-43ff28d649cb changed its status to Valid Thread-21::DEBUG::2014-11-25 14:55:38,113::misc::821::Storage.Event.Storage.DomainMonitor.onDomainStateChange::(_emit) Emitting event Thread-18::INFO::2014-11-25 14:55:38,113::clusterlock::222::Storage.SANLock::(acquireHostId) Acquiring host id for domain ea499cc0-684f-4a2f-abef-43ff28d649cb (id: 1) Thread-21::DEBUG::2014-11-25 14:55:38,115::misc::831::Storage.Event.Storage.DomainMonitor.onDomainStateChange::(_emit) Calling registered method `contEIOVms` Thread-17::DEBUG::2014-11-25 14:55:38,115::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/43.252.176.12:_var_lib_exports_iso/9b2fdce9-a795-44a7-86ed-99e514d24399/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None) Thread-18::DEBUG::2014-11-25 14:55:38,116::clusterlock::240::Storage.SANLock::(acquireHostId) Host id for domain ea499cc0-684f-4a2f-abef-43ff28d649cb successfully acquired (id: 1) Thread-21::DEBUG::2014-11-25 14:55:38,122::misc::841::Storage.Event.Storage.DomainMonitor.onDomainStateChange::(_emit) Event emitted Thread-22::INFO::2014-11-25 14:55:38,124::clientIF::136::vds::(contEIOVms) vmContainerLock acquired Thread-17::DEBUG::2014-11-25 14:55:38,126::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: = '0+1 records in\n0+1 records out\n438 bytes (438 B) copied, 0.000245464 s, 1.8 MB/s\n'; = 0 Thread-14::DEBUG::2014-11-25 14:55:38,126::__init__::232::IOProcess::(_processLogs) Receiving request... Thread-14::DEBUG::2014-11-25 14:55:38,127::__init__::232::IOProcess::(_processLogs) Queuing request in the thread pool... Thread-14::DEBUG::2014-11-25 14:55:38,127::__init__::232::IOProcess::(_processLogs) Extracting request information... Thread-14::DEBUG::2014-11-25 14:55:38,127::__init__::232::IOProcess::(_processLogs) (22) Got request for method 'statvfs' Thread-14::DEBUG::2014-11-25 14:55:38,127::__init__::232::IOProcess::(_processLogs) (22) Queuing response Thread-17::DEBUG::2014-11-25 14:55:38,128::domainMonitor::264::Storage.DomainMonitorThread::(_monitorDomain) Domain 9b2fdce9-a795-44a7-86ed-99e514d24399 changed its status to Valid Thread-23::DEBUG::2014-11-25 14:55:38,128::misc::821::Storage.Event.Storage.DomainMonitor.onDomainStateChange::(_emit) Emitting event Thread-23::DEBUG::2014-11-25 14:55:38,129::misc::831::Storage.Event.Storage.DomainMonitor.onDomainStateChange::(_emit) Calling registered method `contEIOVms` Thread-23::DEBUG::2014-11-25 14:55:38,129::misc::841::Storage.Event.Storage.DomainMonitor.onDomainStateChange::(_emit) Event emitted Thread-24::INFO::2014-11-25 14:55:38,130::clientIF::136::vds::(contEIOVms) vmContainerLock acquired Thread-13::DEBUG::2014-11-25 14:55:38,336::lvm::288::Storage.Misc.excCmd::(cmd) FAILED: = ' Volume group "9b2fdce9-a795-44a7-86ed-99e514d24399" not found\n Skipping volume group 9b2fdce9-a795-44a7-86ed-99e514d24399\n'; = 5 Thread-13::WARNING::2014-11-25 14:55:38,337::lvm::370::Storage.LVM::(_reloadvgs) lvm vgs failed: 5 [] [' Volume group "9b2fdce9-a795-44a7-86ed-99e514d24399" not found', ' Skipping volume group 9b2fdce9-a795-44a7-86ed-99e514d24399'] Thread-13::DEBUG::2014-11-25 14:55:38,337::lvm::407::Storage.OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex Thread-14::DEBUG::2014-11-25 14:55:38,340::__init__::232::IOProcess::(_processLogs) Receiving request... Thread-14::DEBUG::2014-11-25 14:55:38,340::__init__::232::IOProcess::(_processLogs) Queuing request in the thread pool... Thread-14::DEBUG::2014-11-25 14:55:38,340::__init__::232::IOProcess::(_processLogs) Extracting request information... Thread-14::DEBUG::2014-11-25 14:55:38,340::__init__::232::IOProcess::(_processLogs) (23) Got request for method 'glob' Thread-14::DEBUG::2014-11-25 14:55:38,341::__init__::232::IOProcess::(_processLogs) (23) Queuing response Thread-14::DEBUG::2014-11-25 14:55:38,341::__init__::232::IOProcess::(_processLogs) Receiving request... Thread-14::DEBUG::2014-11-25 14:55:38,342::__init__::232::IOProcess::(_processLogs) Queuing request in the thread pool... Thread-14::DEBUG::2014-11-25 14:55:38,342::__init__::232::IOProcess::(_processLogs) Extracting request information... Thread-14::DEBUG::2014-11-25 14:55:38,342::__init__::232::IOProcess::(_processLogs) (24) Got request for method 'glob' Thread-14::DEBUG::2014-11-25 14:55:38,348::__init__::232::IOProcess::(_processLogs) (24) Queuing response Thread-13::INFO::2014-11-25 14:55:38,349::sp::1120::Storage.StoragePool::(_linkStorageDomain) Linking /rhev/data-center/mnt/43.252.176.12:_var_lib_exports_iso/9b2fdce9-a795-44a7-86ed-99e514d24399 to /rhev/data-center/f4966810-0923-4752-a054-2b4954584970/9b2fdce9-a795-44a7-86ed-99e514d24399 Thread-13::DEBUG::2014-11-25 14:55:38,349::sp::1137::Storage.StoragePool::(_linkStorageDomain) Creating symlink from /rhev/data-center/mnt/43.252.176.12:_var_lib_exports_iso/9b2fdce9-a795-44a7-86ed-99e514d24399 to /rhev/data-center/f4966810-0923-4752-a054-2b4954584970/9b2fdce9-a795-44a7-86ed-99e514d24399 Thread-13::INFO::2014-11-25 14:55:38,350::sp::1120::Storage.StoragePool::(_linkStorageDomain) Linking /rhev/data-center/mnt/glusterSD/10.10.10.3:_data1/ea499cc0-684f-4a2f-abef-43ff28d649cb to /rhev/data-center/f4966810-0923-4752-a054-2b4954584970/ea499cc0-684f-4a2f-abef-43ff28d649cb Thread-13::DEBUG::2014-11-25 14:55:38,350::sp::1137::Storage.StoragePool::(_linkStorageDomain) Creating symlink from /rhev/data-center/mnt/glusterSD/10.10.10.3:_data1/ea499cc0-684f-4a2f-abef-43ff28d649cb to /rhev/data-center/f4966810-0923-4752-a054-2b4954584970/ea499cc0-684f-4a2f-abef-43ff28d649cb Thread-13::INFO::2014-11-25 14:55:38,350::sp::1120::Storage.StoragePool::(_linkStorageDomain) Linking /rhev/data-center/mnt/glusterSD/10.10.10.3:_data1/ea499cc0-684f-4a2f-abef-43ff28d649cb to /rhev/data-center/f4966810-0923-4752-a054-2b4954584970/mastersd Thread-13::DEBUG::2014-11-25 14:55:38,350::sp::1137::Storage.StoragePool::(_linkStorageDomain) Creating symlink from /rhev/data-center/mnt/glusterSD/10.10.10.3:_data1/ea499cc0-684f-4a2f-abef-43ff28d649cb to /rhev/data-center/f4966810-0923-4752-a054-2b4954584970/mastersd Thread-13::DEBUG::2014-11-25 14:55:38,358::threadPool::35::Storage.ThreadPool::(__init__) Enter - numThreads: 5, waitTimeout: 3, maxTasks: 500 Thread-13::DEBUG::2014-11-25 14:55:38,361::storage_mailbox::84::Storage.Misc.excCmd::(_mboxExecCmd) /bin/dd if=/rhev/data-center/f4966810-0923-4752-a054-2b4954584970/mastersd/dom_md/outbox iflag=direct,fullblock bs=512 count=8 skip=8 (cwd None) Thread-13::DEBUG::2014-11-25 14:55:38,373::storage_mailbox::84::Storage.Misc.excCmd::(_mboxExecCmd) SUCCESS: = '8+0 records in\n8+0 records out\n4096 bytes (4.1 kB) copied, 0.00722556 s, 567 kB/s\n'; = 0 Thread-13::INFO::2014-11-25 14:55:38,373::storage_mailbox::385::Storage.MailBox.HsmMailMonitor::(_sendMail) HSM_MailMonitor sending mail to SPM - ['/bin/dd', 'of=/rhev/data-center/f4966810-0923-4752-a054-2b4954584970/mastersd/dom_md/inbox', 'iflag=fullblock', 'oflag=direct', 'conv=notrunc', 'bs=512', 'seek=8'] Thread-13::DEBUG::2014-11-25 14:55:38,374::storage_mailbox::84::Storage.Misc.excCmd::(_mboxExecCmd) /bin/dd of=/rhev/data-center/f4966810-0923-4752-a054-2b4954584970/mastersd/dom_md/inbox iflag=fullblock oflag=direct conv=notrunc bs=512 seek=8 (cwd None) Thread-13::DEBUG::2014-11-25 14:55:38,381::storage_mailbox::84::Storage.Misc.excCmd::(_mboxExecCmd) SUCCESS: = '8+0 records in\n8+0 records out\n4096 bytes (4.1 kB) copied, 0.00236082 s, 1.7 MB/s\n'; = 0 Thread-13::DEBUG::2014-11-25 14:55:38,382::storage_mailbox::207::Storage.Mailbox.HSM::(__init__) HSM_MailboxMonitor created for pool f4966810-0923-4752-a054-2b4954584970 Thread-13::DEBUG::2014-11-25 14:55:38,382::sp::462::Storage.StoragePool::(__createMailboxMonitor) HSM mailbox ready for pool f4966810-0923-4752-a054-2b4954584970 on master domain ea499cc0-684f-4a2f-abef-43ff28d649cb Thread-13::DEBUG::2014-11-25 14:55:38,382::resourceManager::616::Storage.ResourceManager::(releaseResource) Trying to release resource 'Storage.f4966810-0923-4752-a054-2b4954584970' Thread-13::DEBUG::2014-11-25 14:55:38,382::resourceManager::635::Storage.ResourceManager::(releaseResource) Released resource 'Storage.f4966810-0923-4752-a054-2b4954584970' (0 active users) Thread-13::DEBUG::2014-11-25 14:55:38,383::resourceManager::641::Storage.ResourceManager::(releaseResource) Resource 'Storage.f4966810-0923-4752-a054-2b4954584970' is free, finding out if anyone is waiting for it. Thread-13::DEBUG::2014-11-25 14:55:38,383::resourceManager::649::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'Storage.f4966810-0923-4752-a054-2b4954584970', Clearing records. Thread-13::DEBUG::2014-11-25 14:55:38,383::resourceManager::616::Storage.ResourceManager::(releaseResource) Trying to release resource 'Storage.HsmDomainMonitorLock' Thread-13::DEBUG::2014-11-25 14:55:38,383::resourceManager::635::Storage.ResourceManager::(releaseResource) Released resource 'Storage.HsmDomainMonitorLock' (0 active users) Thread-13::DEBUG::2014-11-25 14:55:38,383::resourceManager::641::Storage.ResourceManager::(releaseResource) Resource 'Storage.HsmDomainMonitorLock' is free, finding out if anyone is waiting for it. Thread-13::DEBUG::2014-11-25 14:55:38,383::resourceManager::649::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'Storage.HsmDomainMonitorLock', Clearing records. Thread-13::INFO::2014-11-25 14:55:38,384::logUtils::47::dispatcher::(wrapper) Run and protect: connectStoragePool, Return response: True Thread-13::DEBUG::2014-11-25 14:55:38,384::task::1191::Storage.TaskManager.Task::(prepare) Task=`0bbd8080-ab4c-49a2-9708-49e6e5bd0b78`::finished: True Thread-13::DEBUG::2014-11-25 14:55:38,384::task::595::Storage.TaskManager.Task::(_updateState) Task=`0bbd8080-ab4c-49a2-9708-49e6e5bd0b78`::moving from state preparing -> state finished Thread-13::DEBUG::2014-11-25 14:55:38,384::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-13::DEBUG::2014-11-25 14:55:38,384::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-13::DEBUG::2014-11-25 14:55:38,385::task::993::Storage.TaskManager.Task::(_decref) Task=`0bbd8080-ab4c-49a2-9708-49e6e5bd0b78`::ref 0 aborting False Thread-13::DEBUG::2014-11-25 14:55:38,435::task::595::Storage.TaskManager.Task::(_updateState) Task=`bcfa1276-fd54-4abc-9f99-b4f0d5a65bc1`::moving from state init -> state preparing Thread-13::INFO::2014-11-25 14:55:38,435::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None) Thread-13::INFO::2014-11-25 14:55:38,435::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'9b2fdce9-a795-44a7-86ed-99e514d24399': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000245464', 'lastCheck': '0.3', 'valid': True}, 'ea499cc0-684f-4a2f-abef-43ff28d649cb': {'code': 0, 'version': 3, 'acquired': False, 'delay': '0.000480957', 'lastCheck': '0.3', 'valid': True}} Thread-13::DEBUG::2014-11-25 14:55:38,435::task::1191::Storage.TaskManager.Task::(prepare) Task=`bcfa1276-fd54-4abc-9f99-b4f0d5a65bc1`::finished: {'9b2fdce9-a795-44a7-86ed-99e514d24399': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000245464', 'lastCheck': '0.3', 'valid': True}, 'ea499cc0-684f-4a2f-abef-43ff28d649cb': {'code': 0, 'version': 3, 'acquired': False, 'delay': '0.000480957', 'lastCheck': '0.3', 'valid': True}} Thread-13::DEBUG::2014-11-25 14:55:38,435::task::595::Storage.TaskManager.Task::(_updateState) Task=`bcfa1276-fd54-4abc-9f99-b4f0d5a65bc1`::moving from state preparing -> state finished Thread-13::DEBUG::2014-11-25 14:55:38,435::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-13::DEBUG::2014-11-25 14:55:38,436::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-13::DEBUG::2014-11-25 14:55:38,436::task::993::Storage.TaskManager.Task::(_decref) Task=`bcfa1276-fd54-4abc-9f99-b4f0d5a65bc1`::ref 0 aborting False Thread-13::DEBUG::2014-11-25 14:55:38,877::BindingXMLRPC::1132::vds::(wrapper) client [10.10.10.2]::call setMOMPolicyParameters with ({'balloonEnabled': False, 'ksmEnabled': False},) {} flowID [5d2c0061] Thread-13::DEBUG::2014-11-25 14:55:38,951::BindingXMLRPC::1139::vds::(wrapper) return setMOMPolicyParameters with {'status': {'message': 'Done', 'code': 0}} Thread-13::DEBUG::2014-11-25 14:55:39,011::BindingXMLRPC::1132::vds::(wrapper) client [10.10.10.2]::call hostUUIDGet with () {} flowID [5d2c0061] Thread-13::DEBUG::2014-11-25 14:55:39,041::BindingXMLRPC::1139::vds::(wrapper) return hostUUIDGet with {'status': {'message': 'Done', 'code': 0}, 'uuid': '918cef1f-ed83-4570-90ad-39c5ceec753c'} Thread-13::DEBUG::2014-11-25 14:55:41,730::BindingXMLRPC::1132::vds::(wrapper) client [10.10.10.2]::call volumesList with () {} Thread-13::DEBUG::2014-11-25 14:55:41,740::BindingXMLRPC::1139::vds::(wrapper) return volumesList with {'status': {'message': 'Done', 'code': 0}, 'volumes': {'data1': {'transportType': ['TCP'], 'uuid': 'e6117925-79b1-417b-9d07-cfc31f68bc51', 'bricks': ['compute1.3linux.com:/brick1', 'compute2.3linux.com:/brick3', 'compute3.3linux.com:/brick5', 'compute4.3linux.com:/brick7', 'compute1.3linux.com:/brick2', 'compute2.3linux.com:/brick4', 'compute3.3linux.com:/brick6', 'compute4.3linux.com:/brick8'], 'volumeName': 'data1', 'volumeType': 'DISTRIBUTED_REPLICATE', 'replicaCount': '2', 'brickCount': '8', 'distCount': '2', 'volumeStatus': 'ONLINE', 'stripeCount': '1', 'bricksInfo': [{'name': 'compute1.3linux.com:/brick1', 'hostUuid': '69b19f4e-03c8-4fe1-a644-2701c41d7020'}, {'name': 'compute2.3linux.com:/brick3', 'hostUuid': '2cf3428c-62be-42f4-86d3-ef67e7dfc97f'}, {'name': 'compute3.3linux.com:/brick5', 'hostUuid': '0d94d896-e994-4deb-b1a1-d6f68be86c30'}, {'name': 'compute4.3linux.com:/brick7', 'hostUuid': '918cef1f-ed83-4570-90ad-39c5ceec753c'}, {'name': 'compute1.3linux.com:/brick2', 'hostUuid': '69b19f4e-03c8-4fe1-a644-2701c41d7020'}, {'name': 'compute2.3linux.com:/brick4', 'hostUuid': '2cf3428c-62be-42f4-86d3-ef67e7dfc97f'}, {'name': 'compute3.3linux.com:/brick6', 'hostUuid': '0d94d896-e994-4deb-b1a1-d6f68be86c30'}, {'name': 'compute4.3linux.com:/brick8', 'hostUuid': '918cef1f-ed83-4570-90ad-39c5ceec753c'}], 'options': {'cluster.server-quorum-type': 'server', 'cluster.eager-lock': 'enable', 'performance.stat-prefetch': 'off', 'auth.allow': '*', 'cluster.quorum-type': 'auto', 'performance.quick-read': 'off', 'network.remote-dio': 'enable', 'nfs.disable': 'off', 'performance.io-cache': 'off', 'storage.owner-uid': '36', 'user.cifs': 'enable', 'performance.read-ahead': 'off', 'storage.owner-gid': '36'}}}} Thread-13::DEBUG::2014-11-25 14:55:47,078::BindingXMLRPC::1132::vds::(wrapper) client [10.10.10.2]::call volumesList with () {} Thread-13::DEBUG::2014-11-25 14:55:47,089::BindingXMLRPC::1139::vds::(wrapper) return volumesList with {'status': {'message': 'Done', 'code': 0}, 'volumes': {'data1': {'transportType': ['TCP'], 'uuid': 'e6117925-79b1-417b-9d07-cfc31f68bc51', 'bricks': ['compute1.3linux.com:/brick1', 'compute2.3linux.com:/brick3', 'compute3.3linux.com:/brick5', 'compute4.3linux.com:/brick7', 'compute1.3linux.com:/brick2', 'compute2.3linux.com:/brick4', 'compute3.3linux.com:/brick6', 'compute4.3linux.com:/brick8'], 'volumeName': 'data1', 'volumeType': 'DISTRIBUTED_REPLICATE', 'replicaCount': '2', 'brickCount': '8', 'distCount': '2', 'volumeStatus': 'ONLINE', 'stripeCount': '1', 'bricksInfo': [{'name': 'compute1.3linux.com:/brick1', 'hostUuid': '69b19f4e-03c8-4fe1-a644-2701c41d7020'}, {'name': 'compute2.3linux.com:/brick3', 'hostUuid': '2cf3428c-62be-42f4-86d3-ef67e7dfc97f'}, {'name': 'compute3.3linux.com:/brick5', 'hostUuid': '0d94d896-e994-4deb-b1a1-d6f68be86c30'}, {'name': 'compute4.3linux.com:/brick7', 'hostUuid': '918cef1f-ed83-4570-90ad-39c5ceec753c'}, {'name': 'compute1.3linux.com:/brick2', 'hostUuid': '69b19f4e-03c8-4fe1-a644-2701c41d7020'}, {'name': 'compute2.3linux.com:/brick4', 'hostUuid': '2cf3428c-62be-42f4-86d3-ef67e7dfc97f'}, {'name': 'compute3.3linux.com:/brick6', 'hostUuid': '0d94d896-e994-4deb-b1a1-d6f68be86c30'}, {'name': 'compute4.3linux.com:/brick8', 'hostUuid': '918cef1f-ed83-4570-90ad-39c5ceec753c'}], 'options': {'cluster.server-quorum-type': 'server', 'cluster.eager-lock': 'enable', 'performance.stat-prefetch': 'off', 'auth.allow': '*', 'cluster.quorum-type': 'auto', 'performance.quick-read': 'off', 'network.remote-dio': 'enable', 'nfs.disable': 'off', 'performance.io-cache': 'off', 'storage.owner-uid': '36', 'user.cifs': 'enable', 'performance.read-ahead': 'off', 'storage.owner-gid': '36'}}}} Thread-14::DEBUG::2014-11-25 14:55:48,124::__init__::232::IOProcess::(_processLogs) Receiving request... Thread-14::DEBUG::2014-11-25 14:55:48,124::__init__::232::IOProcess::(_processLogs) Queuing request in the thread pool... Thread-14::DEBUG::2014-11-25 14:55:48,124::__init__::232::IOProcess::(_processLogs) Extracting request information... Thread-14::DEBUG::2014-11-25 14:55:48,125::__init__::232::IOProcess::(_processLogs) (25) Got request for method 'statvfs' Thread-14::DEBUG::2014-11-25 14:55:48,129::__init__::232::IOProcess::(_processLogs) Receiving request... Thread-14::DEBUG::2014-11-25 14:55:48,129::__init__::232::IOProcess::(_processLogs) Queuing request in the thread pool... Thread-14::DEBUG::2014-11-25 14:55:48,129::__init__::232::IOProcess::(_processLogs) Extracting request information... Thread-14::DEBUG::2014-11-25 14:55:48,130::__init__::232::IOProcess::(_processLogs) (26) Got request for method 'statvfs' Thread-14::DEBUG::2014-11-25 14:55:48,130::__init__::232::IOProcess::(_processLogs) (25) Queuing response Thread-14::DEBUG::2014-11-25 14:55:48,131::__init__::232::IOProcess::(_processLogs) (26) Queuing response Thread-18::DEBUG::2014-11-25 14:55:48,133::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/glusterSD/10.10.10.3:_data1/ea499cc0-684f-4a2f-abef-43ff28d649cb/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None) Thread-17::DEBUG::2014-11-25 14:55:48,139::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/43.252.176.12:_var_lib_exports_iso/9b2fdce9-a795-44a7-86ed-99e514d24399/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None) Thread-18::DEBUG::2014-11-25 14:55:48,144::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: = '0+1 records in\n0+1 records out\n540 bytes (540 B) copied, 0.000493893 s, 1.1 MB/s\n'; = 0 Thread-17::DEBUG::2014-11-25 14:55:48,147::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: = '0+1 records in\n0+1 records out\n438 bytes (438 B) copied, 0.000305819 s, 1.4 MB/s\n'; = 0 Thread-14::DEBUG::2014-11-25 14:55:48,148::__init__::232::IOProcess::(_processLogs) Receiving request... Thread-14::DEBUG::2014-11-25 14:55:48,149::__init__::232::IOProcess::(_processLogs) Queuing request in the thread pool... Thread-14::DEBUG::2014-11-25 14:55:48,149::__init__::232::IOProcess::(_processLogs) Extracting request information... Thread-14::DEBUG::2014-11-25 14:55:48,150::__init__::232::IOProcess::(_processLogs) (27) Got request for method 'statvfs' Thread-14::DEBUG::2014-11-25 14:55:48,150::__init__::232::IOProcess::(_processLogs) (27) Queuing response Thread-14::DEBUG::2014-11-25 14:55:48,151::__init__::232::IOProcess::(_processLogs) Receiving request... Thread-14::DEBUG::2014-11-25 14:55:48,152::__init__::232::IOProcess::(_processLogs) Queuing request in the thread pool... Thread-14::DEBUG::2014-11-25 14:55:48,152::__init__::232::IOProcess::(_processLogs) Extracting request information... Thread-14::DEBUG::2014-11-25 14:55:48,152::__init__::232::IOProcess::(_processLogs) (28) Got request for method 'statvfs' Thread-14::DEBUG::2014-11-25 14:55:48,152::__init__::232::IOProcess::(_processLogs) (28) Queuing response Thread-14::DEBUG::2014-11-25 14:55:48,153::__init__::232::IOProcess::(_processLogs) Receiving request... Thread-14::DEBUG::2014-11-25 14:55:48,155::__init__::232::IOProcess::(_processLogs) Queuing request in the thread pool... Thread-14::DEBUG::2014-11-25 14:55:48,155::__init__::232::IOProcess::(_processLogs) Extracting request information... Thread-14::DEBUG::2014-11-25 14:55:48,156::__init__::232::IOProcess::(_processLogs) (29) Got request for method 'access' Thread-14::DEBUG::2014-11-25 14:55:48,156::__init__::232::IOProcess::(_processLogs) (29) Queuing response Thread-14::DEBUG::2014-11-25 14:55:48,157::__init__::232::IOProcess::(_processLogs) Receiving request... Thread-14::DEBUG::2014-11-25 14:55:48,157::__init__::232::IOProcess::(_processLogs) Queuing request in the thread pool... Thread-14::DEBUG::2014-11-25 14:55:48,157::__init__::232::IOProcess::(_processLogs) Extracting request information... Thread-14::DEBUG::2014-11-25 14:55:48,157::__init__::232::IOProcess::(_processLogs) (30) Got request for method 'access' Thread-14::DEBUG::2014-11-25 14:55:48,157::__init__::232::IOProcess::(_processLogs) (30) Queuing response Thread-14::DEBUG::2014-11-25 14:55:48,158::__init__::232::IOProcess::(_processLogs) Receiving request... Thread-14::DEBUG::2014-11-25 14:55:48,158::__init__::232::IOProcess::(_processLogs) Queuing request in the thread pool... Thread-14::DEBUG::2014-11-25 14:55:48,159::__init__::232::IOProcess::(_processLogs) Extracting request information... Thread-14::DEBUG::2014-11-25 14:55:48,159::__init__::232::IOProcess::(_processLogs) (31) Got request for method 'access' Thread-14::DEBUG::2014-11-25 14:55:48,159::__init__::232::IOProcess::(_processLogs) (31) Queuing response Thread-13::DEBUG::2014-11-25 14:55:52,416::BindingXMLRPC::1132::vds::(wrapper) client [10.10.10.2]::call volumesList with () {} Thread-13::DEBUG::2014-11-25 14:55:52,429::BindingXMLRPC::1139::vds::(wrapper) return volumesList with {'status': {'message': 'Done', 'code': 0}, 'volumes': {'data1': {'transportType': ['TCP'], 'uuid': 'e6117925-79b1-417b-9d07-cfc31f68bc51', 'bricks': ['compute1.3linux.com:/brick1', 'compute2.3linux.com:/brick3', 'compute3.3linux.com:/brick5', 'compute4.3linux.com:/brick7', 'compute1.3linux.com:/brick2', 'compute2.3linux.com:/brick4', 'compute3.3linux.com:/brick6', 'compute4.3linux.com:/brick8'], 'volumeName': 'data1', 'volumeType': 'DISTRIBUTED_REPLICATE', 'replicaCount': '2', 'brickCount': '8', 'distCount': '2', 'volumeStatus': 'ONLINE', 'stripeCount': '1', 'bricksInfo': [{'name': 'compute1.3linux.com:/brick1', 'hostUuid': '69b19f4e-03c8-4fe1-a644-2701c41d7020'}, {'name': 'compute2.3linux.com:/brick3', 'hostUuid': '2cf3428c-62be-42f4-86d3-ef67e7dfc97f'}, {'name': 'compute3.3linux.com:/brick5', 'hostUuid': '0d94d896-e994-4deb-b1a1-d6f68be86c30'}, {'name': 'compute4.3linux.com:/brick7', 'hostUuid': '918cef1f-ed83-4570-90ad-39c5ceec753c'}, {'name': 'compute1.3linux.com:/brick2', 'hostUuid': '69b19f4e-03c8-4fe1-a644-2701c41d7020'}, {'name': 'compute2.3linux.com:/brick4', 'hostUuid': '2cf3428c-62be-42f4-86d3-ef67e7dfc97f'}, {'name': 'compute3.3linux.com:/brick6', 'hostUuid': '0d94d896-e994-4deb-b1a1-d6f68be86c30'}, {'name': 'compute4.3linux.com:/brick8', 'hostUuid': '918cef1f-ed83-4570-90ad-39c5ceec753c'}], 'options': {'cluster.server-quorum-type': 'server', 'cluster.eager-lock': 'enable', 'performance.stat-prefetch': 'off', 'auth.allow': '*', 'cluster.quorum-type': 'auto', 'performance.quick-read': 'off', 'network.remote-dio': 'enable', 'nfs.disable': 'off', 'performance.io-cache': 'off', 'storage.owner-uid': '36', 'user.cifs': 'enable', 'performance.read-ahead': 'off', 'storage.owner-gid': '36'}}}} Thread-13::DEBUG::2014-11-25 14:55:54,321::task::595::Storage.TaskManager.Task::(_updateState) Task=`6ff3a7bd-adb7-4730-b885-4940f9f85a9b`::moving from state init -> state preparing Thread-13::INFO::2014-11-25 14:55:54,321::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None) Thread-13::INFO::2014-11-25 14:55:54,322::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'9b2fdce9-a795-44a7-86ed-99e514d24399': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000305819', 'lastCheck': '6.2', 'valid': True}, 'ea499cc0-684f-4a2f-abef-43ff28d649cb': {'code': 0, 'version': 3, 'acquired': False, 'delay': '0.000493893', 'lastCheck': '6.2', 'valid': True}} Thread-13::DEBUG::2014-11-25 14:55:54,322::task::1191::Storage.TaskManager.Task::(prepare) Task=`6ff3a7bd-adb7-4730-b885-4940f9f85a9b`::finished: {'9b2fdce9-a795-44a7-86ed-99e514d24399': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000305819', 'lastCheck': '6.2', 'valid': True}, 'ea499cc0-684f-4a2f-abef-43ff28d649cb': {'code': 0, 'version': 3, 'acquired': False, 'delay': '0.000493893', 'lastCheck': '6.2', 'valid': True}} Thread-13::DEBUG::2014-11-25 14:55:54,322::task::595::Storage.TaskManager.Task::(_updateState) Task=`6ff3a7bd-adb7-4730-b885-4940f9f85a9b`::moving from state preparing -> state finished Thread-13::DEBUG::2014-11-25 14:55:54,322::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-13::DEBUG::2014-11-25 14:55:54,322::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-13::DEBUG::2014-11-25 14:55:54,322::task::993::Storage.TaskManager.Task::(_decref) Task=`6ff3a7bd-adb7-4730-b885-4940f9f85a9b`::ref 0 aborting False Thread-13::DEBUG::2014-11-25 14:55:57,749::BindingXMLRPC::1132::vds::(wrapper) client [10.10.10.2]::call volumesList with () {} Thread-13::DEBUG::2014-11-25 14:55:57,761::BindingXMLRPC::1139::vds::(wrapper) return volumesList with {'status': {'message': 'Done', 'code': 0}, 'volumes': {'data1': {'transportType': ['TCP'], 'uuid': 'e6117925-79b1-417b-9d07-cfc31f68bc51', 'bricks': ['compute1.3linux.com:/brick1', 'compute2.3linux.com:/brick3', 'compute3.3linux.com:/brick5', 'compute4.3linux.com:/brick7', 'compute1.3linux.com:/brick2', 'compute2.3linux.com:/brick4', 'compute3.3linux.com:/brick6', 'compute4.3linux.com:/brick8'], 'volumeName': 'data1', 'volumeType': 'DISTRIBUTED_REPLICATE', 'replicaCount': '2', 'brickCount': '8', 'distCount': '2', 'volumeStatus': 'ONLINE', 'stripeCount': '1', 'bricksInfo': [{'name': 'compute1.3linux.com:/brick1', 'hostUuid': '69b19f4e-03c8-4fe1-a644-2701c41d7020'}, {'name': 'compute2.3linux.com:/brick3', 'hostUuid': '2cf3428c-62be-42f4-86d3-ef67e7dfc97f'}, {'name': 'compute3.3linux.com:/brick5', 'hostUuid': '0d94d896-e994-4deb-b1a1-d6f68be86c30'}, {'name': 'compute4.3linux.com:/brick7', 'hostUuid': '918cef1f-ed83-4570-90ad-39c5ceec753c'}, {'name': 'compute1.3linux.com:/brick2', 'hostUuid': '69b19f4e-03c8-4fe1-a644-2701c41d7020'}, {'name': 'compute2.3linux.com:/brick4', 'hostUuid': '2cf3428c-62be-42f4-86d3-ef67e7dfc97f'}, {'name': 'compute3.3linux.com:/brick6', 'hostUuid': '0d94d896-e994-4deb-b1a1-d6f68be86c30'}, {'name': 'compute4.3linux.com:/brick8', 'hostUuid': '918cef1f-ed83-4570-90ad-39c5ceec753c'}], 'options': {'cluster.server-quorum-type': 'server', 'cluster.eager-lock': 'enable', 'performance.stat-prefetch': 'off', 'auth.allow': '*', 'cluster.quorum-type': 'auto', 'performance.quick-read': 'off', 'network.remote-dio': 'enable', 'nfs.disable': 'off', 'performance.io-cache': 'off', 'storage.owner-uid': '36', 'user.cifs': 'enable', 'performance.read-ahead': 'off', 'storage.owner-gid': '36'}}}} Thread-14::DEBUG::2014-11-25 14:55:58,156::__init__::232::IOProcess::(_processLogs) Receiving request... Thread-14::DEBUG::2014-11-25 14:55:58,156::__init__::232::IOProcess::(_processLogs) Queuing request in the thread pool... Thread-14::DEBUG::2014-11-25 14:55:58,157::__init__::232::IOProcess::(_processLogs) Extracting request information... Thread-14::DEBUG::2014-11-25 14:55:58,157::__init__::232::IOProcess::(_processLogs) (32) Got request for method 'statvfs' Thread-14::DEBUG::2014-11-25 14:55:58,157::__init__::232::IOProcess::(_processLogs) (32) Queuing response Thread-17::DEBUG::2014-11-25 14:55:58,158::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/43.252.176.12:_var_lib_exports_iso/9b2fdce9-a795-44a7-86ed-99e514d24399/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None) Thread-17::DEBUG::2014-11-25 14:55:58,165::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: = '0+1 records in\n0+1 records out\n438 bytes (438 B) copied, 0.000302494 s, 1.4 MB/s\n'; = 0 Thread-14::DEBUG::2014-11-25 14:55:58,166::__init__::232::IOProcess::(_processLogs) Receiving request... Thread-14::DEBUG::2014-11-25 14:55:58,167::__init__::232::IOProcess::(_processLogs) Queuing request in the thread pool... Thread-14::DEBUG::2014-11-25 14:55:58,168::__init__::232::IOProcess::(_processLogs) Extracting request information... Thread-14::DEBUG::2014-11-25 14:55:58,168::__init__::232::IOProcess::(_processLogs) (33) Got request for method 'statvfs' Thread-14::DEBUG::2014-11-25 14:55:58,168::__init__::232::IOProcess::(_processLogs) (33) Queuing response Thread-14::DEBUG::2014-11-25 14:55:58,169::__init__::232::IOProcess::(_processLogs) Receiving request... Thread-18::DEBUG::2014-11-25 14:55:58,170::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/glusterSD/10.10.10.3:_data1/ea499cc0-684f-4a2f-abef-43ff28d649cb/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None) Thread-14::DEBUG::2014-11-25 14:55:58,170::__init__::232::IOProcess::(_processLogs) Queuing request in the thread pool... Thread-14::DEBUG::2014-11-25 14:55:58,176::__init__::232::IOProcess::(_processLogs) Extracting request information... Thread-14::DEBUG::2014-11-25 14:55:58,176::__init__::232::IOProcess::(_processLogs) (34) Got request for method 'statvfs' Thread-14::DEBUG::2014-11-25 14:55:58,176::__init__::232::IOProcess::(_processLogs) (34) Queuing response Thread-18::DEBUG::2014-11-25 14:55:58,179::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: = '0+1 records in\n0+1 records out\n540 bytes (540 B) copied, 0.00041774 s, 1.3 MB/s\n'; = 0 Thread-14::DEBUG::2014-11-25 14:55:58,179::__init__::232::IOProcess::(_processLogs) Receiving request... Thread-14::DEBUG::2014-11-25 14:55:58,179::__init__::232::IOProcess::(_processLogs) Queuing request in the thread pool... Thread-14::DEBUG::2014-11-25 14:55:58,180::__init__::232::IOProcess::(_processLogs) Extracting request information... Thread-14::DEBUG::2014-11-25 14:55:58,180::__init__::232::IOProcess::(_processLogs) (35) Got request for method 'statvfs' Thread-14::DEBUG::2014-11-25 14:55:58,180::__init__::232::IOProcess::(_processLogs) (35) Queuing response Thread-14::DEBUG::2014-11-25 14:55:58,181::__init__::232::IOProcess::(_processLogs) Receiving request... Thread-14::DEBUG::2014-11-25 14:55:58,181::__init__::232::IOProcess::(_processLogs) Queuing request in the thread pool... Thread-14::DEBUG::2014-11-25 14:55:58,181::__init__::232::IOProcess::(_processLogs) Extracting request information... Thread-14::DEBUG::2014-11-25 14:55:58,181::__init__::232::IOProcess::(_processLogs) (36) Got request for method 'access' Thread-14::DEBUG::2014-11-25 14:55:58,182::__init__::232::IOProcess::(_processLogs) (36) Queuing response Thread-14::DEBUG::2014-11-25 14:55:58,182::__init__::232::IOProcess::(_processLogs) Receiving request... Thread-14::DEBUG::2014-11-25 14:55:58,183::__init__::232::IOProcess::(_processLogs) Queuing request in the thread pool... Thread-14::DEBUG::2014-11-25 14:55:58,183::__init__::232::IOProcess::(_processLogs) Extracting request information... Thread-14::DEBUG::2014-11-25 14:55:58,183::__init__::232::IOProcess::(_processLogs) (37) Got request for method 'access' Thread-14::DEBUG::2014-11-25 14:55:58,183::__init__::232::IOProcess::(_processLogs) (37) Queuing response Thread-14::DEBUG::2014-11-25 14:55:58,184::__init__::232::IOProcess::(_processLogs) Receiving request... Thread-14::DEBUG::2014-11-25 14:55:58,184::__init__::232::IOProcess::(_processLogs) Queuing request in the thread pool... Thread-14::DEBUG::2014-11-25 14:55:58,184::__init__::232::IOProcess::(_processLogs) Extracting request information... Thread-14::DEBUG::2014-11-25 14:55:58,184::__init__::232::IOProcess::(_processLogs) (38) Got request for method 'access' Thread-14::DEBUG::2014-11-25 14:55:58,185::__init__::232::IOProcess::(_processLogs) (38) Queuing response