Attachment 864563 Details for Bug 1044068 – verifying vdsm log.

verifying vdsm log.

vdsm.log (text/x-log), 191.30 KB, created by Carlos Mestre González on 2014-02-18 13:44:38 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Carlos Mestre González

Created: 2014-02-18 13:44:38 UTC

Size: 191.30 KB

patch

obsolete

>Thread-1261::DEBUG::2014-02-18 14:34:09,784::BindingXMLRPC::977::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'RebootInProgress', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'guestFQDN': '', 'pid': '8479', 'displayIp': '0', 'displayPort': u'5900', 'session': 'Unknown', 'displaySecurePort': u'5901', 'timeOffset': '0', 'hash': '1178642822739702423', 'balloonInfo': {'balloon_max': '1048576', 'balloon_target': '1048576', 'balloon_cur': '1048576', 'balloon_min': '1048576'}, 'pauseCode': 'NOERR', 'clientIp': '10.34.131.114', 'kvmEnable': 'true', 'network': {u'vnet0': {'macAddr': '00:1a:4a:30:3f:16', 'rxDropped': '0', 'rxErrors': '0', 'txDropped': '0', 'txRate': '0.1', 'rxRate': '2.7', 'txErrors': '0', 'state': 'unknown', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': '1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f', 'displayType': 'qxl', 'cpuUser': '67.01', 'disks': {u'vda': {'readLatency': '484046', 'apparentsize': '0', 'writeLatency': '1438744', 'flushLatency': '14030892', 'readRate': '146425.86', 'truesize': '0', 'writeRate': '841923.12'}, u'hdc': {'readLatency': '0', 'apparentsize': '0', 'writeLatency': '0', 'flushLatency': '0', 'readRate': '0.00', 'truesize': '0', 'writeRate': '0.00'}}, 'monitorResponse': '0', 'statsAge': '0.16', 'elapsedTime': '26', 'vmType': 'kvm', 'cpuSys': '40.12', 'appsList': [], 'guestIPs': ''}]}
>Thread-153::DEBUG::2014-02-18 14:34:11,596::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.199:_cmg02/227ac6ed-39b0-4e18-a007-7dc7180b4905/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-153::DEBUG::2014-02-18 14:34:11,601::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n451 bytes (451 B) copied, 0.000302888 s, 1.5 MB/s\n'; <rc> = 0
>VM Channels Listener::DEBUG::2014-02-18 14:34:11,838::vmChannels::91::vds::(_handle_timeouts) Timeout on fileno 13.
>Thread-1262::INFO::2014-02-18 14:34:12,797::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-1262::INFO::2014-02-18 14:34:12,797::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'227ac6ed-39b0-4e18-a007-7dc7180b4905': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000302888', 'lastCheck': '1.2', 'valid': True}}
>Thread-1265::DEBUG::2014-02-18 14:34:15,949::BindingXMLRPC::970::vds::(wrapper) client [10.34.63.25]::call vmGetStats with ('1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f',) {}
>Thread-1265::DEBUG::2014-02-18 14:34:15,950::BindingXMLRPC::977::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'RebootInProgress', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'guestFQDN': '', 'pid': '8479', 'displayIp': '0', 'displayPort': u'5900', 'session': 'Unknown', 'displaySecurePort': u'5901', 'timeOffset': '0', 'hash': '1178642822739702423', 'balloonInfo': {'balloon_max': '1048576', 'balloon_target': '1048576', 'balloon_cur': '1048576', 'balloon_min': '1048576'}, 'pauseCode': 'NOERR', 'clientIp': '10.34.131.114', 'kvmEnable': 'true', 'network': {u'vnet0': {'macAddr': '00:1a:4a:30:3f:16', 'rxDropped': '0', 'rxErrors': '0', 'txDropped': '0', 'txRate': '0.1', 'rxRate': '2.7', 'txErrors': '0', 'state': 'unknown', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': '1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f', 'displayType': 'qxl', 'cpuUser': '67.01', 'disks': {u'vda': {'readLatency': '484046', 'apparentsize': '0', 'writeLatency': '1438744', 'flushLatency': '14030892', 'readRate': '146425.86', 'truesize': '0', 'writeRate': '841923.12'}, u'hdc': {'readLatency': '0', 'apparentsize': '0', 'writeLatency': '0', 'flushLatency': '0', 'readRate': '0.00', 'truesize': '0', 'writeRate': '0.00'}}, 'monitorResponse': '0', 'statsAge': '0.31', 'elapsedTime': '32', 'vmType': 'kvm', 'cpuSys': '40.12', 'appsList': [], 'guestIPs': ''}]}
>Thread-1266::DEBUG::2014-02-18 14:34:16,109::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25]
>Thread-1266::INFO::2014-02-18 14:34:16,109::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-1266::INFO::2014-02-18 14:34:16,121::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 2L}}
>Thread-1267::DEBUG::2014-02-18 14:34:16,129::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25]
>Thread-1267::INFO::2014-02-18 14:34:16,129::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-1267::INFO::2014-02-18 14:34:16,131::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '227ac6ed-39b0-4e18-a007-7dc7180b4905:Active', 'master_uuid': '227ac6ed-39b0-4e18-a007-7dc7180b4905', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'227ac6ed-39b0-4e18-a007-7dc7180b4905': {'status': 'Active', 'diskfree': '142286946304', 'isoprefix': '', 'alerts': [], 'disktotal': '144349954048', 'version': 3}}}
>Thread-1269::DEBUG::2014-02-18 14:34:18,966::BindingXMLRPC::970::vds::(wrapper) client [10.34.63.25]::call vmGetStats with ('1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f',) {}
>Thread-1269::DEBUG::2014-02-18 14:34:18,967::BindingXMLRPC::977::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'RebootInProgress', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'guestFQDN': '', 'pid': '8479', 'displayIp': '0', 'displayPort': u'5900', 'session': 'Unknown', 'displaySecurePort': u'5901', 'timeOffset': '0', 'hash': '1178642822739702423', 'balloonInfo': {'balloon_max': '1048576', 'balloon_target': '1048576', 'balloon_cur': '1048576', 'balloon_min': '1048576'}, 'pauseCode': 'NOERR', 'clientIp': '10.34.131.114', 'kvmEnable': 'true', 'network': {u'vnet0': {'macAddr': '00:1a:4a:30:3f:16', 'rxDropped': '0', 'rxErrors': '0', 'txDropped': '0', 'txRate': '0.1', 'rxRate': '2.7', 'txErrors': '0', 'state': 'unknown', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': '1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f', 'displayType': 'qxl', 'cpuUser': '67.01', 'disks': {u'vda': {'readLatency': '484046', 'apparentsize': '0', 'writeLatency': '1438744', 'flushLatency': '14030892', 'readRate': '146425.86', 'truesize': '0', 'writeRate': '841923.12'}, u'hdc': {'readLatency': '0', 'apparentsize': '0', 'writeLatency': '0', 'flushLatency': '0', 'readRate': '0.00', 'truesize': '0', 'writeRate': '0.00'}}, 'monitorResponse': '0', 'statsAge': '1.33', 'elapsedTime': '35', 'vmType': 'kvm', 'cpuSys': '40.12', 'appsList': [], 'guestIPs': ''}]}
>Thread-153::DEBUG::2014-02-18 14:34:21,608::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.199:_cmg02/227ac6ed-39b0-4e18-a007-7dc7180b4905/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-153::DEBUG::2014-02-18 14:34:21,611::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n451 bytes (451 B) copied, 0.000347021 s, 1.3 MB/s\n'; <rc> = 0
>Thread-1271::DEBUG::2014-02-18 14:34:21,994::BindingXMLRPC::970::vds::(wrapper) client [10.34.63.25]::call vmGetStats with ('1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f',) {}
>Thread-1271::DEBUG::2014-02-18 14:34:21,995::BindingXMLRPC::977::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'RebootInProgress', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'guestFQDN': '', 'pid': '8479', 'displayIp': '0', 'displayPort': u'5900', 'session': 'Unknown', 'displaySecurePort': u'5901', 'timeOffset': '0', 'hash': '1178642822739702423', 'balloonInfo': {'balloon_max': '1048576', 'balloon_target': '1048576', 'balloon_cur': '1048576', 'balloon_min': '1048576'}, 'pauseCode': 'NOERR', 'clientIp': '10.34.131.114', 'kvmEnable': 'true', 'network': {u'vnet0': {'macAddr': '00:1a:4a:30:3f:16', 'rxDropped': '0', 'rxErrors': '0', 'txDropped': '0', 'txRate': '0.1', 'rxRate': '2.7', 'txErrors': '0', 'state': 'unknown', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': '1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f', 'displayType': 'qxl', 'cpuUser': '67.01', 'disks': {u'vda': {'readLatency': '484046', 'apparentsize': '0', 'writeLatency': '1438744', 'flushLatency': '14030892', 'readRate': '146425.86', 'truesize': '0', 'writeRate': '841923.12'}, u'hdc': {'readLatency': '0', 'apparentsize': '0', 'writeLatency': '0', 'flushLatency': '0', 'readRate': '0.00', 'truesize': '0', 'writeRate': '0.00'}}, 'monitorResponse': '0', 'statsAge': '0.35', 'elapsedTime': '38', 'vmType': 'kvm', 'cpuSys': '40.12', 'appsList': [], 'guestIPs': ''}]}
>libvirtEventLoop::DEBUG::2014-02-18 14:34:22,032::clientIF::550::vm.Vm::(dispatchLibvirtEvents) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::graphics event phase 2 localAddr {'node': '10.34.62.206', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.114', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2014-02-18 14:34:22,034::clientIF::550::vm.Vm::(dispatchLibvirtEvents) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::graphics event phase 2 localAddr {'node': '10.34.62.206', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.114', 'service': '', 'family': 0}authScheme spice subject []
>libvirtEventLoop::DEBUG::2014-02-18 14:34:22,034::clientIF::550::vm.Vm::(dispatchLibvirtEvents) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::graphics event phase 2 localAddr {'node': '10.34.62.206', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.114', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2014-02-18 14:34:22,034::clientIF::550::vm.Vm::(dispatchLibvirtEvents) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::graphics event phase 2 localAddr {'node': '10.34.62.206', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.114', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2014-02-18 14:34:22,043::clientIF::550::vm.Vm::(dispatchLibvirtEvents) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::graphics event phase 2 localAddr {'node': '10.34.62.206', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.114', 'service': '', 'family': 0}authScheme  subject []
>Thread-1272::DEBUG::2014-02-18 14:34:24,033::guestIF::278::vm.Vm::(desktopLock) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::desktopLock called
>Thread-1273::DEBUG::2014-02-18 14:34:24,034::guestIF::278::vm.Vm::(desktopLock) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::desktopLock called
>Thread-1274::DEBUG::2014-02-18 14:34:24,034::guestIF::278::vm.Vm::(desktopLock) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::desktopLock called
>Thread-1275::DEBUG::2014-02-18 14:34:24,035::guestIF::278::vm.Vm::(desktopLock) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::desktopLock called
>Thread-1276::DEBUG::2014-02-18 14:34:24,044::guestIF::278::vm.Vm::(desktopLock) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::desktopLock called
>Thread-1278::DEBUG::2014-02-18 14:34:25,015::BindingXMLRPC::970::vds::(wrapper) client [10.34.63.25]::call vmGetStats with ('1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f',) {}
>Thread-1278::DEBUG::2014-02-18 14:34:25,017::BindingXMLRPC::977::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'RebootInProgress', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'guestFQDN': '', 'pid': '8479', 'displayIp': '0', 'displayPort': u'5900', 'session': 'Unknown', 'displaySecurePort': u'5901', 'timeOffset': '0', 'hash': '1178642822739702423', 'balloonInfo': {'balloon_max': '1048576', 'balloon_target': '1048576', 'balloon_cur': '1048576', 'balloon_min': '1048576'}, 'pauseCode': 'NOERR', 'clientIp': '', 'kvmEnable': 'true', 'network': {u'vnet0': {'macAddr': '00:1a:4a:30:3f:16', 'rxDropped': '0', 'rxErrors': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '6.8', 'txErrors': '0', 'state': 'unknown', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': '1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f', 'displayType': 'qxl', 'cpuUser': '7.05', 'disks': {u'vda': {'readLatency': '484046', 'apparentsize': '0', 'writeLatency': '1438744', 'flushLatency': '14030892', 'readRate': '146425.86', 'truesize': '0', 'writeRate': '841923.12'}, u'hdc': {'readLatency': '0', 'apparentsize': '0', 'writeLatency': '0', 'flushLatency': '0', 'readRate': '0.00', 'truesize': '0', 'writeRate': '0.00'}}, 'monitorResponse': '0', 'statsAge': '0.37', 'elapsedTime': '41', 'vmType': 'kvm', 'cpuSys': '4.26', 'appsList': [], 'guestIPs': ''}]}
>libvirtEventLoop::DEBUG::2014-02-18 14:34:26,043::vm::2373::vm.Vm::(onReboot) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::reboot event
>Thread-1279::DEBUG::2014-02-18 14:34:26,168::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25]
>Thread-1279::INFO::2014-02-18 14:34:26,168::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-1279::INFO::2014-02-18 14:34:26,180::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 2L}}
>Thread-1280::DEBUG::2014-02-18 14:34:26,184::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25]
>Thread-1280::INFO::2014-02-18 14:34:26,184::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-1280::INFO::2014-02-18 14:34:26,187::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '227ac6ed-39b0-4e18-a007-7dc7180b4905:Active', 'master_uuid': '227ac6ed-39b0-4e18-a007-7dc7180b4905', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'227ac6ed-39b0-4e18-a007-7dc7180b4905': {'status': 'Active', 'diskfree': '142286946304', 'isoprefix': '', 'alerts': [], 'disktotal': '144349954048', 'version': 3}}}
>Thread-1281::INFO::2014-02-18 14:34:28,165::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-1281::INFO::2014-02-18 14:34:28,165::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'227ac6ed-39b0-4e18-a007-7dc7180b4905': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000347021', 'lastCheck': '6.6', 'valid': True}}
>Thread-1283::DEBUG::2014-02-18 14:34:31,158::BindingXMLRPC::970::vds::(wrapper) client [10.34.63.25]::call vmDestroy with ('1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f',) {} flowID [1201d7c]
>Thread-1283::INFO::2014-02-18 14:34:31,158::API::327::vds::(destroy) vmContainerLock acquired by vm 1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f
>Thread-1283::DEBUG::2014-02-18 14:34:31,158::vm::4604::vm.Vm::(destroy) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::destroy Called
>Thread-1283::INFO::2014-02-18 14:34:31,158::vm::4550::vm.Vm::(releaseVm) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Release VM resources
>Thread-1283::DEBUG::2014-02-18 14:34:31,165::sampling::292::vm.Vm::(stop) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Stop statistics collection
>Thread-388::DEBUG::2014-02-18 14:34:31,165::sampling::323::vm.Vm::(run) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Stats thread finished
>Thread-1283::DEBUG::2014-02-18 14:34:31,166::vmChannels::205::vds::(unregister) Delete fileno 13 from listener.
>Thread-153::DEBUG::2014-02-18 14:34:31,620::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.199:_cmg02/227ac6ed-39b0-4e18-a007-7dc7180b4905/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-153::DEBUG::2014-02-18 14:34:31,625::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n451 bytes (451 B) copied, 0.000330902 s, 1.4 MB/s\n'; <rc> = 0
>libvirtEventLoop::DEBUG::2014-02-18 14:34:31,645::vm::5087::vm.Vm::(_onLibvirtLifecycleEvent) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::event Stopped detail 1 opaque None
>libvirtEventLoop::INFO::2014-02-18 14:34:31,645::vm::2308::vm.Vm::(_onQemuDeath) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::underlying process disconnected
>Thread-1283::WARNING::2014-02-18 14:34:31,645::clientIF::332::vds::(teardownVolumePath) Drive is not a vdsm image: VOLWM_CHUNK_MB:1024 VOLWM_CHUNK_REPLICATE_MULT:2 VOLWM_FREE_PCT:50 _blockDev:False _checkIoTuneCategories:<bound method Drive._checkIoTuneCategories of <vm.Drive object at 0x7f1fe45fdfd0>> _customize:<bound method Drive._customize of <vm.Drive object at 0x7f1fe45fdfd0>> _deviceXML:<disk device="cdrom" snapshot="no" type="file"><source file="" startupPolicy="optional"/><target bus="ide" dev="hdc"/><readonly/><serial></serial></disk> _makeName:<bound method Drive._makeName of <vm.Drive object at 0x7f1fe45fdfd0>> _setExtSharedState:<bound method Drive._setExtSharedState of <vm.Drive object at 0x7f1fe45fdfd0>> _validateIoTuneParams:<bound method Drive._validateIoTuneParams of <vm.Drive object at 0x7f1fe45fdfd0>> address:{u'bus': u'1', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'0'} alias:ide0-1-0 apparentsize:0 blockDev:False cache:none conf:{'status': 'Up', 'acpiEnable': 'true', 'emulatedMachine': 'rhel6.5.0', 'vmId': '1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f', 'pid': '8479', 'memGuaranteedSize': 1024, 'timeOffset': '0', 'keyboardLayout': 'en-us', 'displayPort': u'5900', 'displaySecurePort': u'5901', 'spiceSslCipherSuite': 'DEFAULT', 'cpuType': 'Penryn', 'custom': {}, 'pauseCode': 'NOERR', 'clientIp': '', 'nicModel': 'rtl8139,pv', 'smartcardEnable': 'false', 'kvmEnable': 'true', 'transparentHugePages': 'true', 'devices': [{'target': 1048576, 'alias': u'balloon0', 'specParams': {'model': 'virtio'}, 'deviceId': '179160c6-194e-4870-aa26-26b35b66df43', 'address': {u'slot': u'0x07', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, 'device': 'memballoon', 'type': 'balloon'}, {'index': '0', 'alias': u'scsi0', 'specParams': {}, 'deviceId': 'ca73cb06-9d48-4682-9dd1-00e0cb7fad06', 'address': {u'slot': u'0x04', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, 'device': 'scsi', 'model': 'virtio-scsi', 'type': 'controller'}, {'alias': u'video0', 'specParams': {'vram': '32768', 'heads': '1'}, 'deviceId': '5e07330d-5ec3-47d4-b290-f0518cf3d067', 'address': {u'slot': u'0x02', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, 'device': 'qxl', 'type': 'video'}, {'nicModel': 'pv', 'macAddr': '00:1a:4a:30:3f:16', 'linkActive': True, 'network': 'ovirtmgmt', 'alias': u'net0', 'bootOrder': '1', 'filter': 'vdsm-no-mac-spoofing', 'specParams': {}, 'deviceId': '6fcaacfb-ad1a-4b7a-89f8-ce68bb13960c', 'address': {u'slot': u'0x03', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, 'device': 'bridge', 'type': 'interface', 'name': u'vnet0'}, {'index': '2', 'iface': 'ide', 'name': u'hdc', 'alias': u'ide0-1-0', 'address': {u'bus': u'1', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'0'}, 'specParams': {'path': ''}, 'readonly': 'True', 'deviceId': 'd06fb87c-3646-4586-a83e-86b185880947', 'path': '', 'device': 'cdrom', 'shared': 'false', 'type': 'disk'}, {'index': 0, 'iface': 'virtio', 'name': u'vda', 'format': 'raw', 'bootOrder': u'2', 'address': {u'slot': u'0x06', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, 'specParams': {}, 'readonly': 'False', 'alias': u'virtio-disk0', 'deviceId': '2cdab93d-3bf6-4a50-ba4e-ae3d8934b5e2', 'propagateErrors': 'off', 'type': 'disk', 'device': 'disk', 'shared': 'false', 'path': '/dev/mapper/1cmg02', 'GUID': '1cmg02', 'optional': 'false'}, {'device': u'usb', 'alias': u'usb0', 'type': 'controller', 'address': {u'slot': u'0x01', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x2'}}, {'device': u'ide', 'alias': u'ide0', 'type': 'controller', 'address': {u'slot': u'0x01', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x1'}}, {'device': u'virtio-serial', 'alias': u'virtio-serial0', 'type': 'controller', 'address': {u'slot': u'0x05', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}}, {'device': u'unix', 'alias': u'channel0', 'type': u'channel', 'address': {u'bus': u'0', u'controller': u'0', u'type': u'virtio-serial', u'port': u'1'}}, {'device': u'unix', 'alias': u'channel1', 'type': u'channel', 'address': {u'bus': u'0', u'controller': u'0', u'type': u'virtio-serial', u'port': u'2'}}, {'device': u'spicevmc', 'alias': u'channel2', 'type': u'channel', 'address': {u'bus': u'0', u'controller': u'0', u'type': u'virtio-serial', u'port': u'3'}}], 'smp': '1', 'vmType': 'kvm', 'memSize': 1024, 'displayIp': '0', 'maxVCpus': '160', 'spiceSecureChannels': 'smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard', 'smpCoresPerSocket': '1', 'vmName': 'vm_01', 'display': 'qxl', 'nice': '0'} createXmlElem:<bound method Drive.createXmlElem of <vm.Drive object at 0x7f1fe45fdfd0>> device:cdrom deviceId:d06fb87c-3646-4586-a83e-86b185880947 drv:raw extSharedState:none getLeasesXML:<bound method Drive.getLeasesXML of <vm.Drive object at 0x7f1fe45fdfd0>> getNextVolumeSize:<bound method Drive.getNextVolumeSize of <vm.Drive object at 0x7f1fe45fdfd0>> getXML:<bound method Drive.getXML of <vm.Drive object at 0x7f1fe45fdfd0>> hasVolumeLeases:False iface:ide index:2 isDiskReplicationInProgress:<bound method Drive.isDiskReplicationInProgress of <vm.Drive object at 0x7f1fe45fdfd0>> log:<logUtils.SimpleLogAdapter instance at 0x7f1fe0086830> name:hdc networkDev:False path: readonly:True reqsize:0 serial: shared:false specParams:{'path': ''} transientDisk:False truesize:0 type:cdrom volExtensionChunk:1024 watermarkLimit:536870912
>Traceback (most recent call last):
>  File "/usr/share/vdsm/clientIF.py", line 326, in teardownVolumePath
>    res = self.irs.teardownImage(drive['domainID'],
>  File "/usr/share/vdsm/vm.py", line 1493, in __getitem__
>    raise KeyError(key)
>KeyError: 'domainID'
>Thread-1283::WARNING::2014-02-18 14:34:31,661::clientIF::332::vds::(teardownVolumePath) Drive is not a vdsm image: GUID:1cmg02 VOLWM_CHUNK_MB:1024 VOLWM_CHUNK_REPLICATE_MULT:2 VOLWM_FREE_PCT:50 _blockDev:True _checkIoTuneCategories:<bound method Drive._checkIoTuneCategories of <vm.Drive object at 0x7f1fe45fd050>> _customize:<bound method Drive._customize of <vm.Drive object at 0x7f1fe45fd050>> _deviceXML:<disk device="disk" snapshot="no" type="block"><source dev="/dev/mapper/1cmg02"/><target bus="virtio" dev="vda"/><serial></serial><boot order="2"/><driver cache="none" error_policy="stop" io="native" name="qemu" type="raw"/></disk> _makeName:<bound method Drive._makeName of <vm.Drive object at 0x7f1fe45fd050>> _setExtSharedState:<bound method Drive._setExtSharedState of <vm.Drive object at 0x7f1fe45fd050>> _validateIoTuneParams:<bound method Drive._validateIoTuneParams of <vm.Drive object at 0x7f1fe45fd050>> address:{u'slot': u'0x06', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'} alias:virtio-disk0 apparentsize:0 blockDev:True bootOrder:2 cache:none conf:{'status': 'Up', 'acpiEnable': 'true', 'emulatedMachine': 'rhel6.5.0', 'vmId': '1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f', 'pid': '8479', 'memGuaranteedSize': 1024, 'timeOffset': '0', 'keyboardLayout': 'en-us', 'displayPort': u'5900', 'displaySecurePort': u'5901', 'spiceSslCipherSuite': 'DEFAULT', 'cpuType': 'Penryn', 'custom': {}, 'pauseCode': 'NOERR', 'clientIp': '', 'nicModel': 'rtl8139,pv', 'smartcardEnable': 'false', 'kvmEnable': 'true', 'transparentHugePages': 'true', 'devices': [{'target': 1048576, 'alias': u'balloon0', 'specParams': {'model': 'virtio'}, 'deviceId': '179160c6-194e-4870-aa26-26b35b66df43', 'address': {u'slot': u'0x07', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, 'device': 'memballoon', 'type': 'balloon'}, {'index': '0', 'alias': u'scsi0', 'specParams': {}, 'deviceId': 'ca73cb06-9d48-4682-9dd1-00e0cb7fad06', 'address': {u'slot': u'0x04', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, 'device': 'scsi', 'model': 'virtio-scsi', 'type': 'controller'}, {'alias': u'video0', 'specParams': {'vram': '32768', 'heads': '1'}, 'deviceId': '5e07330d-5ec3-47d4-b290-f0518cf3d067', 'address': {u'slot': u'0x02', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, 'device': 'qxl', 'type': 'video'}, {'nicModel': 'pv', 'macAddr': '00:1a:4a:30:3f:16', 'linkActive': True, 'network': 'ovirtmgmt', 'alias': u'net0', 'bootOrder': '1', 'filter': 'vdsm-no-mac-spoofing', 'specParams': {}, 'deviceId': '6fcaacfb-ad1a-4b7a-89f8-ce68bb13960c', 'address': {u'slot': u'0x03', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, 'device': 'bridge', 'type': 'interface', 'name': u'vnet0'}, {'index': '2', 'iface': 'ide', 'name': u'hdc', 'alias': u'ide0-1-0', 'address': {u'bus': u'1', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'0'}, 'specParams': {'path': ''}, 'readonly': 'True', 'deviceId': 'd06fb87c-3646-4586-a83e-86b185880947', 'path': '', 'device': 'cdrom', 'shared': 'false', 'type': 'disk'}, {'index': 0, 'iface': 'virtio', 'name': u'vda', 'format': 'raw', 'bootOrder': u'2', 'address': {u'slot': u'0x06', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, 'specParams': {}, 'readonly': 'False', 'alias': u'virtio-disk0', 'deviceId': '2cdab93d-3bf6-4a50-ba4e-ae3d8934b5e2', 'propagateErrors': 'off', 'type': 'disk', 'device': 'disk', 'shared': 'false', 'path': '/dev/mapper/1cmg02', 'GUID': '1cmg02', 'optional': 'false'}, {'device': u'usb', 'alias': u'usb0', 'type': 'controller', 'address': {u'slot': u'0x01', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x2'}}, {'device': u'ide', 'alias': u'ide0', 'type': 'controller', 'address': {u'slot': u'0x01', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x1'}}, {'device': u'virtio-serial', 'alias': u'virtio-serial0', 'type': 'controller', 'address': {u'slot': u'0x05', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}}, {'device': u'unix', 'alias': u'channel0', 'type': u'channel', 'address': {u'bus': u'0', u'controller': u'0', u'type': u'virtio-serial', u'port': u'1'}}, {'device': u'unix', 'alias': u'channel1', 'type': u'channel', 'address': {u'bus': u'0', u'controller': u'0', u'type': u'virtio-serial', u'port': u'2'}}, {'device': u'spicevmc', 'alias': u'channel2', 'type': u'channel', 'address': {u'bus': u'0', u'controller': u'0', u'type': u'virtio-serial', u'port': u'3'}}], 'smp': '1', 'vmType': 'kvm', 'memSize': 1024, 'displayIp': '0', 'maxVCpus': '160', 'spiceSecureChannels': 'smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard', 'smpCoresPerSocket': '1', 'vmName': 'vm_01', 'display': 'qxl', 'nice': '0'} createXmlElem:<bound method Drive.createXmlElem of <vm.Drive object at 0x7f1fe45fd050>> device:disk deviceId:2cdab93d-3bf6-4a50-ba4e-ae3d8934b5e2 drv:raw extSharedState:none format:raw getLeasesXML:<bound method Drive.getLeasesXML of <vm.Drive object at 0x7f1fe45fd050>> getNextVolumeSize:<bound method Drive.getNextVolumeSize of <vm.Drive object at 0x7f1fe45fd050>> getXML:<bound method Drive.getXML of <vm.Drive object at 0x7f1fe45fd050>> hasVolumeLeases:False iface:virtio index:0 isDiskReplicationInProgress:<bound method Drive.isDiskReplicationInProgress of <vm.Drive object at 0x7f1fe45fd050>> log:<logUtils.SimpleLogAdapter instance at 0x7f1fe0086830> name:vda networkDev:False optional:false path:/dev/mapper/1cmg02 propagateErrors:off readonly:False reqsize:0 serial: shared:false specParams:{} transientDisk:False truesize:0 type:disk volExtensionChunk:1024 watermarkLimit:536870912
>Traceback (most recent call last):
>  File "/usr/share/vdsm/clientIF.py", line 326, in teardownVolumePath
>    res = self.irs.teardownImage(drive['domainID'],
>  File "/usr/share/vdsm/vm.py", line 1493, in __getitem__
>    raise KeyError(key)
>KeyError: 'domainID'
>Thread-1283::INFO::2014-02-18 14:34:31,663::logUtils::44::dispatcher::(wrapper) Run and protect: inappropriateDevices(thiefId='1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f')
>Thread-1283::INFO::2014-02-18 14:34:31,672::logUtils::47::dispatcher::(wrapper) Run and protect: inappropriateDevices, Return response: None
>Thread-1283::DEBUG::2014-02-18 14:34:31,673::vm::4598::vm.Vm::(deleteVm) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Total desktops after destroy of 1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f is 0
>Thread-1283::DEBUG::2014-02-18 14:34:31,673::BindingXMLRPC::977::vds::(wrapper) return vmDestroy with {'status': {'message': 'Machine destroyed', 'code': 0}}
>libvirtEventLoop::DEBUG::2014-02-18 14:34:31,674::libvirtconnection::124::root::(wrapper) Unknown libvirterror: ecode: 42 edom: 10 level: 2 message: Domain not found: no domain with matching uuid '1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f'
>libvirtEventLoop::DEBUG::2014-02-18 14:34:31,675::vm::2714::vm.Vm::(setDownStatus) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Changed state to Down: Admin shut down
>libvirtEventLoop::DEBUG::2014-02-18 14:34:31,675::sampling::292::vm.Vm::(stop) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Stop statistics collection
>libvirtEventLoop::DEBUG::2014-02-18 14:34:31,677::libvirtconnection::124::root::(wrapper) Unknown libvirterror: ecode: 42 edom: 10 level: 2 message: Domain not found: no domain with matching uuid '1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f'
>VM Channels Listener::DEBUG::2014-02-18 14:34:31,861::vmChannels::112::vds::(_do_del_channels) fileno 13 was removed from listener.
>Thread-1286::DEBUG::2014-02-18 14:34:36,258::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25]
>Thread-1286::INFO::2014-02-18 14:34:36,259::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-1286::INFO::2014-02-18 14:34:36,270::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 2L}}
>Thread-1287::DEBUG::2014-02-18 14:34:36,275::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25]
>Thread-1287::INFO::2014-02-18 14:34:36,275::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-1287::INFO::2014-02-18 14:34:36,278::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '227ac6ed-39b0-4e18-a007-7dc7180b4905:Active', 'master_uuid': '227ac6ed-39b0-4e18-a007-7dc7180b4905', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'227ac6ed-39b0-4e18-a007-7dc7180b4905': {'status': 'Active', 'diskfree': '142286946304', 'isoprefix': '', 'alerts': [], 'disktotal': '144349954048', 'version': 3}}}
>Thread-1289::DEBUG::2014-02-18 14:34:39,573::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25] flowID [3f100c05]
>Thread-1289::INFO::2014-02-18 14:34:39,574::logUtils::44::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=3, spUUID='00000002-0002-0002-0002-000000000002', conList=[{'connection': '10.34.63.202', 'iqn': 'iqn.2012-10.brq.str-01:cmestreg', 'portal': '1', 'user': '', 'password': '******', 'id': 'f7c28cc2-985f-4977-b4b0-f19c30c788da', 'port': '3260'}], options=None)
>Thread-1289::DEBUG::2014-02-18 14:34:39,574::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m node -T iqn.2012-10.brq.str-01:cmestreg -I default -p 10.34.63.202:3260 --op=new' (cwd None)
>Thread-1289::DEBUG::2014-02-18 14:34:39,590::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-1289::DEBUG::2014-02-18 14:34:39,590::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m node -T iqn.2012-10.brq.str-01:cmestreg -I default -p 10.34.63.202:3260 -l' (cwd None)
>Thread-1289::DEBUG::2014-02-18 14:34:39,598::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-1289::DEBUG::2014-02-18 14:34:39,598::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m node -T iqn.2012-10.brq.str-01:cmestreg -I default -p 10.34.63.202:3260 -n node.startup -v manual --op=update' (cwd None)
>Thread-1289::DEBUG::2014-02-18 14:34:39,606::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-1289::DEBUG::2014-02-18 14:34:39,607::lvm::295::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/1cmg01|/dev/mapper/1cmg02|\', \'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,lv_count,pv_count,pv_name' (cwd None)
>Thread-1289::DEBUG::2014-02-18 14:34:39,739::lvm::295::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-1289::DEBUG::2014-02-18 14:34:39,740::hsm::2325::Storage.HSM::(__prefetchDomains) Found SD uuids: ('afcb2944-8c5d-4d60-af6b-d95db3e904ac',)
>Thread-1289::DEBUG::2014-02-18 14:34:39,741::hsm::2381::Storage.HSM::(connectStorageServer) knownSDs: {3f620296-84b7-49f2-bb20-41e68cdadfbc: storage.nfsSD.findDomain, 227ac6ed-39b0-4e18-a007-7dc7180b4905: storage.nfsSD.findDomain, afcb2944-8c5d-4d60-af6b-d95db3e904ac: storage.blockSD.findDomain, 6116a097-264f-40f2-9c37-b0a1d79b1dd2: storage.blockSD.findDomain}
>Thread-1289::INFO::2014-02-18 14:34:39,741::logUtils::47::dispatcher::(wrapper) Run and protect: connectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': 'f7c28cc2-985f-4977-b4b0-f19c30c788da'}]}
>Thread-1290::DEBUG::2014-02-18 14:34:39,797::BindingXMLRPC::970::vds::(wrapper) client [10.34.63.25]::call vmCreate with ({'acpiEnable': 'true', 'emulatedMachine': 'rhel6.5.0', 'vmId': '1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f', 'memGuaranteedSize': 1024, 'spiceSslCipherSuite': 'DEFAULT', 'timeOffset': '0', 'cpuType': 'Penryn', 'smp': '1', 'custom': {'device_620dc094-2376-4a95-8f44-bb32f655de63device_ddb1bf74-0a4d-4a1d-b81c-75de674b703bdevice_9a5d8b59-ce55-4a64-b473-a9ee5ed06146device_bc18d987-298b-42ce-9108-865c7bef0bc5': 'VmDevice {vmId=1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f, deviceId=bc18d987-298b-42ce-9108-865c7bef0bc5, device=unix, type=CHANNEL, bootOrder=0, specParams={}, address={port=1, bus=0, controller=0, type=virtio-serial}, managed=false, plugged=true, readOnly=false, deviceAlias=channel0, customProperties={}, snapshotId=null}', 'device_620dc094-2376-4a95-8f44-bb32f655de63device_ddb1bf74-0a4d-4a1d-b81c-75de674b703bdevice_9a5d8b59-ce55-4a64-b473-a9ee5ed06146': 'VmDevice {vmId=1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f, deviceId=9a5d8b59-ce55-4a64-b473-a9ee5ed06146, device=virtio-serial, type=CONTROLLER, bootOrder=0, specParams={}, address={bus=0x00, domain=0x0000, type=pci, slot=0x05, function=0x0}, managed=false, plugged=true, readOnly=false, deviceAlias=virtio-serial0, customProperties={}, snapshotId=null}', 'device_620dc094-2376-4a95-8f44-bb32f655de63device_ddb1bf74-0a4d-4a1d-b81c-75de674b703bdevice_9a5d8b59-ce55-4a64-b473-a9ee5ed06146device_bc18d987-298b-42ce-9108-865c7bef0bc5device_15c4273a-bfa6-419e-b166-8cecbf53a017device_4cb71313-c2ac-49c1-bfc1-50ef6211edfe': 'VmDevice {vmId=1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f, deviceId=4cb71313-c2ac-49c1-bfc1-50ef6211edfe, device=spicevmc, type=CHANNEL, bootOrder=0, specParams={}, address={port=3, bus=0, controller=0, type=virtio-serial}, managed=false, plugged=true, readOnly=false, deviceAlias=channel2, customProperties={}, snapshotId=null}', 'device_620dc094-2376-4a95-8f44-bb32f655de63device_ddb1bf74-0a4d-4a1d-b81c-75de674b703bdevice_9a5d8b59-ce55-4a64-b473-a9ee5ed06146device_bc18d987-298b-42ce-9108-865c7bef0bc5device_15c4273a-bfa6-419e-b166-8cecbf53a017': 'VmDevice {vmId=1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f, deviceId=15c4273a-bfa6-419e-b166-8cecbf53a017, device=unix, type=CHANNEL, bootOrder=0, specParams={}, address={port=2, bus=0, controller=0, type=virtio-serial}, managed=false, plugged=true, readOnly=false, deviceAlias=channel1, customProperties={}, snapshotId=null}', 'device_620dc094-2376-4a95-8f44-bb32f655de63device_ddb1bf74-0a4d-4a1d-b81c-75de674b703b': 'VmDevice {vmId=1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f, deviceId=ddb1bf74-0a4d-4a1d-b81c-75de674b703b, device=ide, type=CONTROLLER, bootOrder=0, specParams={}, address={bus=0x00, domain=0x0000, type=pci, slot=0x01, function=0x1}, managed=false, plugged=true, readOnly=false, deviceAlias=ide0, customProperties={}, snapshotId=null}', 'device_620dc094-2376-4a95-8f44-bb32f655de63': 'VmDevice {vmId=1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f, deviceId=620dc094-2376-4a95-8f44-bb32f655de63, device=memballoon, type=BALLOON, bootOrder=0, specParams={model=virtio}, address={bus=0x00, domain=0x0000, type=pci, slot=0x07, function=0x0}, managed=false, plugged=true, readOnly=false, deviceAlias=balloon0, customProperties={}, snapshotId=null}'}, 'vmType': 'kvm', 'memSize': 1024, 'smpCoresPerSocket': '1', 'vmName': 'vm_01', 'nice': '0', 'smartcardEnable': 'false', 'keyboardLayout': 'en-us', 'kvmEnable': 'true', 'transparentHugePages': 'true', 'devices': [{'device': 'qxl', 'specParams': {'vram': '32768', 'heads': '1'}, 'type': 'video', 'deviceId': '5e07330d-5ec3-47d4-b290-f0518cf3d067', 'address': {'slot': '0x02', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}}, {'index': '2', 'iface': 'ide', 'address': {'bus': '1', 'controller': '0', 'type': 'drive', 'target': '0', 'unit': '0'}, 'specParams': {'path': ''}, 'readonly': 'true', 'deviceId': 'd06fb87c-3646-4586-a83e-86b185880947', 'path': '', 'device': 'cdrom', 'shared': 'false', 'type': 'disk'}, {'index': 0, 'iface': 'virtio', 'type': 'disk', 'format': 'raw', 'bootOrder': '1', 'specParams': {}, 'readonly': 'false', 'deviceId': '2cdab93d-3bf6-4a50-ba4e-ae3d8934b5e2', 'propagateErrors': 'off', 'address': {'slot': '0x06', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'disk', 'shared': 'false', 'GUID': '1cmg02', 'optional': 'false'}, {'nicModel': 'pv', 'macAddr': '00:1a:4a:30:3f:16', 'linkActive': 'true', 'network': 'ovirtmgmt', 'bootOrder': '2', 'filter': 'vdsm-no-mac-spoofing', 'specParams': {}, 'deviceId': '6fcaacfb-ad1a-4b7a-89f8-ce68bb13960c', 'address': {'slot': '0x03', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'bridge', 'type': 'interface'}, {'device': 'memballoon', 'specParams': {'model': 'virtio'}, 'type': 'balloon', 'deviceId': '9f07aed9-1708-48e9-9ccd-0f73ad55f31c'}, {'index': '0', 'specParams': {}, 'deviceId': 'ca73cb06-9d48-4682-9dd1-00e0cb7fad06', 'address': {'slot': '0x04', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'scsi', 'model': 'virtio-scsi', 'type': 'controller'}], 'maxVCpus': '160', 'spiceSecureChannels': 'smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard', 'display': 'qxl'},) {} flowID [3f100c05]
>Thread-1290::INFO::2014-02-18 14:34:39,799::API::668::vds::(_getNetworkIp) network None: using 0
>Thread-1290::INFO::2014-02-18 14:34:39,799::clientIF::361::vds::(createVm) vmContainerLock acquired by vm 1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f
>Thread-1290::DEBUG::2014-02-18 14:34:39,802::clientIF::374::vds::(createVm) Total desktops after creation of 1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f is 1
>Thread-1291::DEBUG::2014-02-18 14:34:39,802::vm::2226::vm.Vm::(_startUnderlyingVm) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Start
>Thread-1290::DEBUG::2014-02-18 14:34:39,802::BindingXMLRPC::977::vds::(wrapper) return vmCreate with {'status': {'message': 'Done', 'code': 0}, 'vmList': {'status': 'WaitForLaunch', 'acpiEnable': 'true', 'emulatedMachine': 'rhel6.5.0', 'vmId': '1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f', 'pid': '0', 'memGuaranteedSize': 1024, 'timeOffset': '0', 'keyboardLayout': 'en-us', 'displayPort': '-1', 'displaySecurePort': '-1', 'spiceSslCipherSuite': 'DEFAULT', 'cpuType': 'Penryn', 'custom': {'device_620dc094-2376-4a95-8f44-bb32f655de63device_ddb1bf74-0a4d-4a1d-b81c-75de674b703bdevice_9a5d8b59-ce55-4a64-b473-a9ee5ed06146device_bc18d987-298b-42ce-9108-865c7bef0bc5': 'VmDevice {vmId=1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f, deviceId=bc18d987-298b-42ce-9108-865c7bef0bc5, device=unix, type=CHANNEL, bootOrder=0, specParams={}, address={port=1, bus=0, controller=0, type=virtio-serial}, managed=false, plugged=true, readOnly=false, deviceAlias=channel0, customProperties={}, snapshotId=null}', 'device_620dc094-2376-4a95-8f44-bb32f655de63device_ddb1bf74-0a4d-4a1d-b81c-75de674b703bdevice_9a5d8b59-ce55-4a64-b473-a9ee5ed06146': 'VmDevice {vmId=1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f, deviceId=9a5d8b59-ce55-4a64-b473-a9ee5ed06146, device=virtio-serial, type=CONTROLLER, bootOrder=0, specParams={}, address={bus=0x00, domain=0x0000, type=pci, slot=0x05, function=0x0}, managed=false, plugged=true, readOnly=false, deviceAlias=virtio-serial0, customProperties={}, snapshotId=null}', 'device_620dc094-2376-4a95-8f44-bb32f655de63device_ddb1bf74-0a4d-4a1d-b81c-75de674b703bdevice_9a5d8b59-ce55-4a64-b473-a9ee5ed06146device_bc18d987-298b-42ce-9108-865c7bef0bc5device_15c4273a-bfa6-419e-b166-8cecbf53a017device_4cb71313-c2ac-49c1-bfc1-50ef6211edfe': 'VmDevice {vmId=1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f, deviceId=4cb71313-c2ac-49c1-bfc1-50ef6211edfe, device=spicevmc, type=CHANNEL, bootOrder=0, specParams={}, address={port=3, bus=0, controller=0, type=virtio-serial}, managed=false, plugged=true, readOnly=false, deviceAlias=channel2, customProperties={}, snapshotId=null}', 'device_620dc094-2376-4a95-8f44-bb32f655de63device_ddb1bf74-0a4d-4a1d-b81c-75de674b703bdevice_9a5d8b59-ce55-4a64-b473-a9ee5ed06146device_bc18d987-298b-42ce-9108-865c7bef0bc5device_15c4273a-bfa6-419e-b166-8cecbf53a017': 'VmDevice {vmId=1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f, deviceId=15c4273a-bfa6-419e-b166-8cecbf53a017, device=unix, type=CHANNEL, bootOrder=0, specParams={}, address={port=2, bus=0, controller=0, type=virtio-serial}, managed=false, plugged=true, readOnly=false, deviceAlias=channel1, customProperties={}, snapshotId=null}', 'device_620dc094-2376-4a95-8f44-bb32f655de63device_ddb1bf74-0a4d-4a1d-b81c-75de674b703b': 'VmDevice {vmId=1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f, deviceId=ddb1bf74-0a4d-4a1d-b81c-75de674b703b, device=ide, type=CONTROLLER, bootOrder=0, specParams={}, address={bus=0x00, domain=0x0000, type=pci, slot=0x01, function=0x1}, managed=false, plugged=true, readOnly=false, deviceAlias=ide0, customProperties={}, snapshotId=null}', 'device_620dc094-2376-4a95-8f44-bb32f655de63': 'VmDevice {vmId=1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f, deviceId=620dc094-2376-4a95-8f44-bb32f655de63, device=memballoon, type=BALLOON, bootOrder=0, specParams={model=virtio}, address={bus=0x00, domain=0x0000, type=pci, slot=0x07, function=0x0}, managed=false, plugged=true, readOnly=false, deviceAlias=balloon0, customProperties={}, snapshotId=null}'}, 'clientIp': '', 'nicModel': 'rtl8139,pv', 'smartcardEnable': 'false', 'kvmEnable': 'true', 'transparentHugePages': 'true', 'devices': [{'device': 'qxl', 'specParams': {'vram': '32768', 'heads': '1'}, 'type': 'video', 'deviceId': '5e07330d-5ec3-47d4-b290-f0518cf3d067', 'address': {'slot': '0x02', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}}, {'index': '2', 'iface': 'ide', 'address': {'bus': '1', 'controller': '0', 'type': 'drive', 'target': '0', 'unit': '0'}, 'specParams': {'path': ''}, 'readonly': 'true', 'deviceId': 'd06fb87c-3646-4586-a83e-86b185880947', 'path': '', 'device': 'cdrom', 'shared': 'false', 'type': 'disk'}, {'index': 0, 'iface': 'virtio', 'type': 'disk', 'format': 'raw', 'bootOrder': '1', 'specParams': {}, 'readonly': 'false', 'deviceId': '2cdab93d-3bf6-4a50-ba4e-ae3d8934b5e2', 'propagateErrors': 'off', 'address': {'slot': '0x06', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'disk', 'shared': 'false', 'GUID': '1cmg02', 'optional': 'false'}, {'nicModel': 'pv', 'macAddr': '00:1a:4a:30:3f:16', 'linkActive': 'true', 'network': 'ovirtmgmt', 'bootOrder': '2', 'filter': 'vdsm-no-mac-spoofing', 'specParams': {}, 'deviceId': '6fcaacfb-ad1a-4b7a-89f8-ce68bb13960c', 'address': {'slot': '0x03', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'bridge', 'type': 'interface'}, {'device': 'memballoon', 'specParams': {'model': 'virtio'}, 'type': 'balloon', 'deviceId': '9f07aed9-1708-48e9-9ccd-0f73ad55f31c'}, {'index': '0', 'specParams': {}, 'deviceId': 'ca73cb06-9d48-4682-9dd1-00e0cb7fad06', 'address': {'slot': '0x04', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'scsi', 'model': 'virtio-scsi', 'type': 'controller'}], 'smp': '1', 'vmType': 'kvm', 'memSize': 1024, 'displayIp': '0', 'maxVCpus': '160', 'spiceSecureChannels': 'smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard', 'smpCoresPerSocket': '1', 'vmName': 'vm_01', 'display': 'qxl', 'nice': '0'}}
>Thread-1291::DEBUG::2014-02-18 14:34:39,803::vm::2230::vm.Vm::(_startUnderlyingVm) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::_ongoingCreations acquired
>Thread-1291::INFO::2014-02-18 14:34:39,803::vm::3080::vm.Vm::(_run) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::VM wrapper has started
>Thread-1291::INFO::2014-02-18 14:34:39,804::clientIF::320::vds::(prepareVolumePath) prepared volume path: 
>Thread-1291::INFO::2014-02-18 14:34:39,806::logUtils::44::dispatcher::(wrapper) Run and protect: getDevicesVisibility(guids=['1cmg02'], options=None)
>Thread-1291::INFO::2014-02-18 14:34:39,807::logUtils::47::dispatcher::(wrapper) Run and protect: getDevicesVisibility, Return response: {'visible': {'1cmg02': True}}
>Thread-1291::INFO::2014-02-18 14:34:39,809::logUtils::44::dispatcher::(wrapper) Run and protect: appropriateDevice(guid='1cmg02', thiefId='1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f')
>Thread-1291::INFO::2014-02-18 14:34:39,875::logUtils::47::dispatcher::(wrapper) Run and protect: appropriateDevice, Return response: None
>Thread-1291::INFO::2014-02-18 14:34:39,879::clientIF::320::vds::(prepareVolumePath) prepared volume path: /dev/mapper/1cmg02
>Thread-1291::DEBUG::2014-02-18 14:34:39,893::vm::3119::vm.Vm::(_run) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::<?xml version="1.0" encoding="utf-8"?>
><domain type="kvm">
>	<name>vm_01</name>
>	<uuid>1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f</uuid>
>	<memory>1048576</memory>
>	<currentMemory>1048576</currentMemory>
>	<vcpu current="1">160</vcpu>
>	<memtune>
>		<min_guarantee>1048576</min_guarantee>
>	</memtune>
>	<devices>
>		<channel type="unix">
>			<target name="com.redhat.rhevm.vdsm" type="virtio"/>
>			<source mode="bind" path="/var/lib/libvirt/qemu/channels/1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f.com.redhat.rhevm.vdsm"/>
>		</channel>
>		<channel type="unix">
>			<target name="org.qemu.guest_agent.0" type="virtio"/>
>			<source mode="bind" path="/var/lib/libvirt/qemu/channels/1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f.org.qemu.guest_agent.0"/>
>		</channel>
>		<input bus="ps2" type="mouse"/>
>		<channel type="spicevmc">
>			<target name="com.redhat.spice.0" type="virtio"/>
>		</channel>
>		<graphics autoport="yes" keymap="en-us" listen="0" passwd="*****" passwdValidTo="1970-01-01T00:00:01" port="-1" tlsPort="-1" type="spice">
>			<channel mode="secure" name="main"/>
>			<channel mode="secure" name="inputs"/>
>			<channel mode="secure" name="cursor"/>
>			<channel mode="secure" name="playback"/>
>			<channel mode="secure" name="record"/>
>			<channel mode="secure" name="display"/>
>			<channel mode="secure" name="usbredir"/>
>			<channel mode="secure" name="smartcard"/>
>		</graphics>
>		<memballoon model="virtio"/>
>		<controller index="0" model="virtio-scsi" type="scsi">
>			<address bus="0x00" domain="0x0000" function="0x0" slot="0x04" type="pci"/>
>		</controller>
>		<video>
>			<address bus="0x00" domain="0x0000" function="0x0" slot="0x02" type="pci"/>
>			<model heads="1" type="qxl" vram="32768"/>
>		</video>
>		<interface type="bridge">
>			<address bus="0x00" domain="0x0000" function="0x0" slot="0x03" type="pci"/>
>			<mac address="00:1a:4a:30:3f:16"/>
>			<model type="virtio"/>
>			<source bridge="ovirtmgmt"/>
>			<filterref filter="vdsm-no-mac-spoofing"/>
>			<link state="up"/>
>			<boot order="2"/>
>		</interface>
>		<disk device="cdrom" snapshot="no" type="file">
>			<address bus="1" controller="0" target="0" type="drive" unit="0"/>
>			<source file="" startupPolicy="optional"/>
>			<target bus="ide" dev="hdc"/>
>			<readonly/>
>			<serial/>
>		</disk>
>		<disk device="disk" snapshot="no" type="block">
>			<address bus="0x00" domain="0x0000" function="0x0" slot="0x06" type="pci"/>
>			<source dev="/dev/mapper/1cmg02"/>
>			<target bus="virtio" dev="vda"/>
>			<serial/>
>			<boot order="1"/>
>			<driver cache="none" error_policy="stop" io="native" name="qemu" type="raw"/>
>		</disk>
>	</devices>
>	<os>
>		<type arch="x86_64" machine="rhel6.5.0">hvm</type>
>		<smbios mode="sysinfo"/>
>	</os>
>	<sysinfo type="smbios">
>		<system>
>			<entry name="manufacturer">oVirt</entry>
>			<entry name="product">oVirt Node</entry>
>			<entry name="version">6Server-6.5.0.1.el6</entry>
>			<entry name="serial">4C4C4544-0033-5310-8052-CAC04F4A354A</entry>
>			<entry name="uuid">1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f</entry>
>		</system>
>	</sysinfo>
>	<clock adjustment="0" offset="variable">
>		<timer name="rtc" tickpolicy="catchup"/>
>	</clock>
>	<features>
>		<acpi/>
>	</features>
>	<cpu match="exact">
>		<model>Penryn</model>
>		<topology cores="1" sockets="160" threads="1"/>
>	</cpu>
></domain>
>
>libvirtEventLoop::DEBUG::2014-02-18 14:34:40,428::vm::5087::vm.Vm::(_onLibvirtLifecycleEvent) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::event Started detail 0 opaque None
>Thread-1291::DEBUG::2014-02-18 14:34:40,445::vm::4961::vm.Vm::(_getUnderlyingDriveInfo) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Looking for drive with attributes {'name': u'hdc', 'bootOrder': '', 'boot': [], 'readonly': True, 'address': {u'bus': u'1', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'0'}, 'path': '', 'type': u'cdrom'}
>Thread-1291::DEBUG::2014-02-18 14:34:40,445::vm::4972::vm.Vm::(_getUnderlyingDriveInfo) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Matched {'name': (u'hdc', u'hdc'), 'bootOrder': ('', None), 'boot': ([], None), 'readonly': (True, True), 'address': ({u'bus': u'1', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'0'}, {u'bus': u'1', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'0'}), 'path': ('', ''), 'type': (u'cdrom', u'cdrom')}
>Thread-1291::DEBUG::2014-02-18 14:34:40,445::vm::4983::vm.Vm::(_getUnderlyingDriveInfo) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Matched {'name': (u'hdc', u'hdc'), 'bootOrder': ('', None), 'boot': ([], None), 'readonly': (True, 'True'), 'address': ({u'bus': u'1', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'0'}, {u'bus': u'1', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'0'}), 'path': ('', ''), 'type': (u'cdrom', 'disk')}
>Thread-1291::DEBUG::2014-02-18 14:34:40,446::vm::4961::vm.Vm::(_getUnderlyingDriveInfo) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Looking for drive with attributes {'name': u'vda', 'bootOrder': u'1', 'boot': [<DOM Element: boot at 0x7f1fd404ec20>], 'readonly': False, 'address': {u'slot': u'0x06', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, 'path': u'/dev/mapper/1cmg02', 'type': u'disk'}
>Thread-1291::DEBUG::2014-02-18 14:34:40,446::vm::4972::vm.Vm::(_getUnderlyingDriveInfo) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Matched {'name': (u'vda', u'vda'), 'bootOrder': (u'1', u'1'), 'boot': ([<DOM Element: boot at 0x7f1fd404ec20>], None), 'readonly': (False, False), 'address': ({u'slot': u'0x06', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, {u'slot': u'0x06', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}), 'path': (u'/dev/mapper/1cmg02', '/dev/mapper/1cmg02'), 'type': (u'disk', u'disk')}
>Thread-1291::DEBUG::2014-02-18 14:34:40,446::vm::4983::vm.Vm::(_getUnderlyingDriveInfo) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Matched {'name': (u'vda', u'vda'), 'bootOrder': (u'1', u'1'), 'boot': ([<DOM Element: boot at 0x7f1fd404ec20>], None), 'readonly': (False, 'False'), 'address': ({u'slot': u'0x06', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, {u'slot': u'0x06', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}), 'path': (u'/dev/mapper/1cmg02', '/dev/mapper/1cmg02'), 'type': (u'disk', 'disk')}
>Thread-1291::DEBUG::2014-02-18 14:34:40,479::sampling::285::vm.Vm::(start) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Start statistics collection
>Thread-1293::DEBUG::2014-02-18 14:34:40,480::sampling::314::vm.Vm::(run) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Stats thread started
>Thread-1291::DEBUG::2014-02-18 14:34:40,482::vmChannels::194::vds::(register) Add fileno 13 to listener's channels.
>Thread-1291::WARNING::2014-02-18 14:34:40,483::vm::3644::vm.Vm::(_readPauseCode) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::_readPauseCode unsupported by libvirt vm
>Thread-1291::DEBUG::2014-02-18 14:34:40,551::vm::2247::vm.Vm::(_startUnderlyingVm) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::_ongoingCreations released
>Thread-1295::DEBUG::2014-02-18 14:34:40,803::BindingXMLRPC::970::vds::(wrapper) client [10.34.63.25]::call vmGetStats with ('1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f',) {}
>Thread-1295::DEBUG::2014-02-18 14:34:40,803::vm::587::vm.Vm::(_getCpuStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::CPU stats not available: 'NoneType' object is unsubscriptable
>Thread-1295::DEBUG::2014-02-18 14:34:40,803::vm::621::vm.Vm::(_getNetworkStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Network stats not available
>Thread-1295::DEBUG::2014-02-18 14:34:40,803::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc stats not available
>Thread-1295::DEBUG::2014-02-18 14:34:40,804::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda stats not available
>Thread-1295::DEBUG::2014-02-18 14:34:40,804::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc latency not available
>Thread-1295::DEBUG::2014-02-18 14:34:40,804::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda latency not available
>Thread-1295::DEBUG::2014-02-18 14:34:40,804::BindingXMLRPC::977::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Powering up', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'guestFQDN': '', 'pid': '663', 'displayIp': '0', 'displayPort': u'5900', 'session': 'Unknown', 'displaySecurePort': u'5901', 'timeOffset': '0', 'hash': '5741667533757168744', 'balloonInfo': {'balloon_max': '1048576', 'balloon_target': '1048576', 'balloon_cur': '1048576', 'balloon_min': '1048576'}, 'pauseCode': 'NOERR', 'clientIp': '', 'kvmEnable': 'true', 'network': {u'vnet0': {'state': 'unknown', 'macAddr': '00:1a:4a:30:3f:16', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': '1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f', 'displayType': 'qxl', 'cpuUser': '0.00', 'disks': {u'vda': {'truesize': '0', 'apparentsize': '0'}, u'hdc': {'truesize': '0', 'apparentsize': '0'}}, 'monitorResponse': '0', 'statsAge': '0.32', 'elapsedTime': '1', 'vmType': 'kvm', 'cpuSys': '0.00', 'appsList': [], 'guestIPs': ''}]}
>VM Channels Listener::DEBUG::2014-02-18 14:34:40,871::vmChannels::102::vds::(_do_add_channels) fileno 13 was added to unconnected channels.
>VM Channels Listener::DEBUG::2014-02-18 14:34:40,871::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 13.
>VM Channels Listener::DEBUG::2014-02-18 14:34:40,871::guestIF::147::vm.Vm::(_connect) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Attempting connection to /var/lib/libvirt/qemu/channels/1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f.com.redhat.rhevm.vdsm
>VM Channels Listener::DEBUG::2014-02-18 14:34:40,872::guestIF::150::vm.Vm::(_connect) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Connected to /var/lib/libvirt/qemu/channels/1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f.com.redhat.rhevm.vdsm
>VM Channels Listener::DEBUG::2014-02-18 14:34:40,872::vmChannels::144::vds::(_handle_unconnected) Connecting to fileno 13 succeeded.
>Thread-153::DEBUG::2014-02-18 14:34:41,637::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.199:_cmg02/227ac6ed-39b0-4e18-a007-7dc7180b4905/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-153::DEBUG::2014-02-18 14:34:41,642::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n451 bytes (451 B) copied, 0.000279904 s, 1.6 MB/s\n'; <rc> = 0
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:34:42,530::vm::587::vm.Vm::(_getCpuStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::CPU stats not available: 'NoneType' object is unsubscriptable
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:34:42,530::vm::621::vm.Vm::(_getNetworkStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Network stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:34:42,530::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:34:42,530::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:34:42,530::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc latency not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:34:42,530::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda latency not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:34:42,531::vm::587::vm.Vm::(_getCpuStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::CPU stats not available: 'NoneType' object is unsubscriptable
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:34:42,531::vm::621::vm.Vm::(_getNetworkStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Network stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:34:42,531::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:34:42,531::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:34:42,532::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc latency not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:34:42,532::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda latency not available
>Thread-1297::INFO::2014-02-18 14:34:43,939::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-1297::INFO::2014-02-18 14:34:43,939::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'227ac6ed-39b0-4e18-a007-7dc7180b4905': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000279904', 'lastCheck': '2.3', 'valid': True}}
>Thread-1298::DEBUG::2014-02-18 14:34:43,964::vm::587::vm.Vm::(_getCpuStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::CPU stats not available: 'NoneType' object is unsubscriptable
>Thread-1298::DEBUG::2014-02-18 14:34:43,964::vm::621::vm.Vm::(_getNetworkStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Network stats not available
>Thread-1298::DEBUG::2014-02-18 14:34:43,964::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc stats not available
>Thread-1298::DEBUG::2014-02-18 14:34:43,964::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda stats not available
>Thread-1298::DEBUG::2014-02-18 14:34:43,964::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc latency not available
>Thread-1298::DEBUG::2014-02-18 14:34:43,964::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda latency not available
>Thread-1299::DEBUG::2014-02-18 14:34:46,300::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25]
>Thread-1299::INFO::2014-02-18 14:34:46,300::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-1299::INFO::2014-02-18 14:34:46,313::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 2L}}
>Thread-1300::DEBUG::2014-02-18 14:34:46,318::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25]
>Thread-1300::INFO::2014-02-18 14:34:46,319::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-1300::INFO::2014-02-18 14:34:46,321::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '227ac6ed-39b0-4e18-a007-7dc7180b4905:Active', 'master_uuid': '227ac6ed-39b0-4e18-a007-7dc7180b4905', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'227ac6ed-39b0-4e18-a007-7dc7180b4905': {'status': 'Active', 'diskfree': '142286946304', 'isoprefix': '', 'alerts': [], 'disktotal': '144349954048', 'version': 3}}}
>Thread-1302::DEBUG::2014-02-18 14:34:47,056::BindingXMLRPC::970::vds::(wrapper) client [10.34.63.25]::call vmGetStats with ('1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f',) {}
>Thread-1302::DEBUG::2014-02-18 14:34:47,056::vm::587::vm.Vm::(_getCpuStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::CPU stats not available: 'NoneType' object is unsubscriptable
>Thread-1302::DEBUG::2014-02-18 14:34:47,056::vm::621::vm.Vm::(_getNetworkStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Network stats not available
>Thread-1302::DEBUG::2014-02-18 14:34:47,056::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc stats not available
>Thread-1302::DEBUG::2014-02-18 14:34:47,056::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda stats not available
>Thread-1302::DEBUG::2014-02-18 14:34:47,056::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc latency not available
>Thread-1302::DEBUG::2014-02-18 14:34:47,056::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda latency not available
>Thread-1302::DEBUG::2014-02-18 14:34:47,057::BindingXMLRPC::977::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Powering up', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'guestFQDN': '', 'pid': '663', 'displayIp': '0', 'displayPort': u'5900', 'session': 'Unknown', 'displaySecurePort': u'5901', 'timeOffset': '0', 'hash': '5741667533757168744', 'balloonInfo': {'balloon_max': '1048576', 'balloon_target': '1048576', 'balloon_cur': '1048576', 'balloon_min': '1048576'}, 'pauseCode': 'NOERR', 'clientIp': '', 'kvmEnable': 'true', 'network': {u'vnet0': {'state': 'unknown', 'macAddr': '00:1a:4a:30:3f:16', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': '1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f', 'displayType': 'qxl', 'cpuUser': '0.00', 'disks': {u'vda': {'truesize': '0', 'apparentsize': '0'}, u'hdc': {'truesize': '0', 'apparentsize': '0'}}, 'monitorResponse': '0', 'statsAge': '0.50', 'elapsedTime': '7', 'vmType': 'kvm', 'cpuSys': '0.00', 'appsList': [], 'guestIPs': ''}]}
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:34:47,537::vm::587::vm.Vm::(_getCpuStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::CPU stats not available: 'NoneType' object is unsubscriptable
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:34:47,537::vm::621::vm.Vm::(_getNetworkStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Network stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:34:47,538::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:34:47,538::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:34:47,538::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc latency not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:34:47,538::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda latency not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:34:47,539::vm::587::vm.Vm::(_getCpuStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::CPU stats not available: 'NoneType' object is unsubscriptable
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:34:47,539::vm::621::vm.Vm::(_getNetworkStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Network stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:34:47,539::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:34:47,539::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:34:47,539::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc latency not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:34:47,539::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda latency not available
>Thread-1304::DEBUG::2014-02-18 14:34:50,073::BindingXMLRPC::970::vds::(wrapper) client [10.34.63.25]::call vmGetStats with ('1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f',) {}
>Thread-1304::DEBUG::2014-02-18 14:34:50,073::vm::587::vm.Vm::(_getCpuStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::CPU stats not available: 'NoneType' object is unsubscriptable
>Thread-1304::DEBUG::2014-02-18 14:34:50,073::vm::621::vm.Vm::(_getNetworkStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Network stats not available
>Thread-1304::DEBUG::2014-02-18 14:34:50,073::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc stats not available
>Thread-1304::DEBUG::2014-02-18 14:34:50,073::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda stats not available
>Thread-1304::DEBUG::2014-02-18 14:34:50,073::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc latency not available
>Thread-1304::DEBUG::2014-02-18 14:34:50,073::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda latency not available
>Thread-1304::DEBUG::2014-02-18 14:34:50,074::BindingXMLRPC::977::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Powering up', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'guestFQDN': '', 'pid': '663', 'displayIp': '0', 'displayPort': u'5900', 'session': 'Unknown', 'displaySecurePort': u'5901', 'timeOffset': '0', 'hash': '5741667533757168744', 'balloonInfo': {'balloon_max': '1048576', 'balloon_target': '1048576', 'balloon_cur': '1048576', 'balloon_min': '1048576'}, 'pauseCode': 'NOERR', 'clientIp': '', 'kvmEnable': 'true', 'network': {u'vnet0': {'state': 'unknown', 'macAddr': '00:1a:4a:30:3f:16', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': '1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f', 'displayType': 'qxl', 'cpuUser': '0.00', 'disks': {u'vda': {'truesize': '0', 'apparentsize': '0'}, u'hdc': {'truesize': '0', 'apparentsize': '0'}}, 'monitorResponse': '0', 'statsAge': '1.51', 'elapsedTime': '10', 'vmType': 'kvm', 'cpuSys': '0.00', 'appsList': [], 'guestIPs': ''}]}
>Thread-1305::DEBUG::2014-02-18 14:34:50,364::BindingXMLRPC::970::vds::(wrapper) client [10.34.63.25]::call vmSetTicket with ('1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f', 'nSGZqKSw4j0x', '120', 'disconnect', {'userName': 'admin', 'userId': 'fdfc627c-d875-11e0-90f0-83df133b58cc'}) {} flowID [2fd1e19e]
>Thread-1305::DEBUG::2014-02-18 14:34:50,418::BindingXMLRPC::977::vds::(wrapper) return vmSetTicket with {'status': {'message': 'Done', 'code': 0}}
>Thread-153::DEBUG::2014-02-18 14:34:51,652::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.199:_cmg02/227ac6ed-39b0-4e18-a007-7dc7180b4905/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-153::DEBUG::2014-02-18 14:34:51,657::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n451 bytes (451 B) copied, 0.000263123 s, 1.7 MB/s\n'; <rc> = 0
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:34:52,545::vm::587::vm.Vm::(_getCpuStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::CPU stats not available: 'NoneType' object is unsubscriptable
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:34:52,545::vm::621::vm.Vm::(_getNetworkStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Network stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:34:52,545::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:34:52,545::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:34:52,546::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc latency not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:34:52,546::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda latency not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:34:52,547::vm::587::vm.Vm::(_getCpuStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::CPU stats not available: 'NoneType' object is unsubscriptable
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:34:52,547::vm::621::vm.Vm::(_getNetworkStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Network stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:34:52,547::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:34:52,547::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:34:52,547::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc latency not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:34:52,547::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda latency not available
>Thread-1307::DEBUG::2014-02-18 14:34:53,095::BindingXMLRPC::970::vds::(wrapper) client [10.34.63.25]::call vmGetStats with ('1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f',) {}
>Thread-1307::DEBUG::2014-02-18 14:34:53,095::vm::587::vm.Vm::(_getCpuStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::CPU stats not available: 'NoneType' object is unsubscriptable
>Thread-1307::DEBUG::2014-02-18 14:34:53,095::vm::621::vm.Vm::(_getNetworkStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Network stats not available
>Thread-1307::DEBUG::2014-02-18 14:34:53,095::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc stats not available
>Thread-1307::DEBUG::2014-02-18 14:34:53,095::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda stats not available
>Thread-1307::DEBUG::2014-02-18 14:34:53,095::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc latency not available
>Thread-1307::DEBUG::2014-02-18 14:34:53,095::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda latency not available
>Thread-1307::DEBUG::2014-02-18 14:34:53,096::BindingXMLRPC::977::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Powering up', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'guestFQDN': '', 'pid': '663', 'displayIp': '0', 'displayPort': u'5900', 'session': 'Unknown', 'displaySecurePort': u'5901', 'timeOffset': '0', 'hash': '5741667533757168744', 'balloonInfo': {'balloon_max': '1048576', 'balloon_target': '1048576', 'balloon_cur': '1048576', 'balloon_min': '1048576'}, 'pauseCode': 'NOERR', 'clientIp': '', 'kvmEnable': 'true', 'network': {u'vnet0': {'state': 'unknown', 'macAddr': '00:1a:4a:30:3f:16', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': '1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f', 'displayType': 'qxl', 'cpuUser': '0.00', 'disks': {u'vda': {'truesize': '0', 'apparentsize': '0'}, u'hdc': {'truesize': '0', 'apparentsize': '0'}}, 'monitorResponse': '0', 'statsAge': '0.54', 'elapsedTime': '13', 'vmType': 'kvm', 'cpuSys': '0.00', 'appsList': [], 'guestIPs': ''}]}
>libvirtEventLoop::DEBUG::2014-02-18 14:34:54,146::clientIF::550::vm.Vm::(dispatchLibvirtEvents) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::graphics event phase 0 localAddr {'node': '10.34.62.206', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.114', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2014-02-18 14:34:54,174::clientIF::550::vm.Vm::(dispatchLibvirtEvents) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::graphics event phase 1 localAddr {'node': '10.34.62.206', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.114', 'service': '', 'family': 0}authScheme spice subject []
>libvirtEventLoop::DEBUG::2014-02-18 14:34:54,225::clientIF::550::vm.Vm::(dispatchLibvirtEvents) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::graphics event phase 0 localAddr {'node': '10.34.62.206', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.114', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2014-02-18 14:34:54,251::clientIF::550::vm.Vm::(dispatchLibvirtEvents) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::graphics event phase 1 localAddr {'node': '10.34.62.206', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.114', 'service': '', 'family': 0}authScheme spice subject []
>libvirtEventLoop::DEBUG::2014-02-18 14:34:54,329::clientIF::550::vm.Vm::(dispatchLibvirtEvents) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::graphics event phase 0 localAddr {'node': '10.34.62.206', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.114', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2014-02-18 14:34:54,343::clientIF::550::vm.Vm::(dispatchLibvirtEvents) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::graphics event phase 0 localAddr {'node': '10.34.62.206', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.114', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2014-02-18 14:34:54,344::clientIF::550::vm.Vm::(dispatchLibvirtEvents) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::graphics event phase 1 localAddr {'node': '10.34.62.206', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.114', 'service': '', 'family': 0}authScheme spice subject []
>libvirtEventLoop::DEBUG::2014-02-18 14:34:54,358::clientIF::550::vm.Vm::(dispatchLibvirtEvents) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::graphics event phase 1 localAddr {'node': '10.34.62.206', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.114', 'service': '', 'family': 0}authScheme spice subject []
>Thread-1309::DEBUG::2014-02-18 14:34:56,112::BindingXMLRPC::970::vds::(wrapper) client [10.34.63.25]::call vmGetStats with ('1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f',) {}
>Thread-1309::DEBUG::2014-02-18 14:34:56,112::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc stats not available
>Thread-1309::DEBUG::2014-02-18 14:34:56,112::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda stats not available
>Thread-1309::DEBUG::2014-02-18 14:34:56,113::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc latency not available
>Thread-1309::DEBUG::2014-02-18 14:34:56,113::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda latency not available
>Thread-1309::DEBUG::2014-02-18 14:34:56,113::BindingXMLRPC::977::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Powering up', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'guestFQDN': '', 'pid': '663', 'displayIp': '0', 'displayPort': u'5900', 'session': 'Unknown', 'displaySecurePort': u'5901', 'timeOffset': '0', 'hash': '5741667533757168744', 'balloonInfo': {'balloon_max': '1048576', 'balloon_target': '1048576', 'balloon_cur': '1048576', 'balloon_min': '1048576'}, 'pauseCode': 'NOERR', 'clientIp': '10.34.131.114', 'kvmEnable': 'true', 'network': {u'vnet0': {'macAddr': '00:1a:4a:30:3f:16', 'rxDropped': '0', 'rxErrors': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '0.0', 'txErrors': '0', 'state': 'unknown', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': '1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f', 'displayType': 'qxl', 'cpuUser': '31.31', 'disks': {u'vda': {'truesize': '0', 'apparentsize': '0'}, u'hdc': {'truesize': '0', 'apparentsize': '0'}}, 'monitorResponse': '0', 'statsAge': '0.55', 'elapsedTime': '16', 'vmType': 'kvm', 'cpuSys': '25.60', 'appsList': [], 'guestIPs': ''}]}
>Thread-1310::DEBUG::2014-02-18 14:34:56,367::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25]
>Thread-1310::INFO::2014-02-18 14:34:56,367::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-1310::INFO::2014-02-18 14:34:56,378::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 2L}}
>Thread-1311::DEBUG::2014-02-18 14:34:56,383::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25]
>Thread-1311::INFO::2014-02-18 14:34:56,383::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-1311::INFO::2014-02-18 14:34:56,385::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '227ac6ed-39b0-4e18-a007-7dc7180b4905:Active', 'master_uuid': '227ac6ed-39b0-4e18-a007-7dc7180b4905', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'227ac6ed-39b0-4e18-a007-7dc7180b4905': {'status': 'Active', 'diskfree': '142286946304', 'isoprefix': '', 'alerts': [], 'disktotal': '144349954048', 'version': 3}}}
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:34:57,553::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:34:57,553::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:34:57,553::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc latency not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:34:57,553::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda latency not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:34:57,554::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:34:57,554::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:34:57,554::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc latency not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:34:57,555::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda latency not available
>libvirtEventLoop::DEBUG::2014-02-18 14:34:57,819::clientIF::550::vm.Vm::(dispatchLibvirtEvents) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::graphics event phase 2 localAddr {'node': '10.34.62.206', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.114', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2014-02-18 14:34:57,819::clientIF::550::vm.Vm::(dispatchLibvirtEvents) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::graphics event phase 2 localAddr {'node': '10.34.62.206', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.114', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2014-02-18 14:34:57,819::clientIF::550::vm.Vm::(dispatchLibvirtEvents) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::graphics event phase 2 localAddr {'node': '10.34.62.206', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.114', 'service': '', 'family': 0}authScheme spice subject []
>libvirtEventLoop::DEBUG::2014-02-18 14:34:57,820::clientIF::550::vm.Vm::(dispatchLibvirtEvents) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::graphics event phase 2 localAddr {'node': '10.34.62.206', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.114', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2014-02-18 14:34:57,820::clientIF::550::vm.Vm::(dispatchLibvirtEvents) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::graphics event phase 2 localAddr {'node': '10.34.62.206', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.114', 'service': '', 'family': 0}authScheme  subject []
>VM Channels Listener::DEBUG::2014-02-18 14:34:58,943::guestIF::209::vm.Vm::(_handleMessage) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::username: u'None'
>VM Channels Listener::DEBUG::2014-02-18 14:34:59,002::guestIF::209::vm.Vm::(_handleMessage) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::username: u'None'
>Thread-1317::INFO::2014-02-18 14:34:59,165::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-1317::INFO::2014-02-18 14:34:59,165::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'227ac6ed-39b0-4e18-a007-7dc7180b4905': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000263123', 'lastCheck': '7.5', 'valid': True}}
>Thread-1318::DEBUG::2014-02-18 14:34:59,180::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc stats not available
>Thread-1318::DEBUG::2014-02-18 14:34:59,180::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda stats not available
>Thread-1318::DEBUG::2014-02-18 14:34:59,180::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc latency not available
>Thread-1318::DEBUG::2014-02-18 14:34:59,180::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda latency not available
>Thread-1312::DEBUG::2014-02-18 14:34:59,819::guestIF::278::vm.Vm::(desktopLock) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::desktopLock called
>Thread-1313::DEBUG::2014-02-18 14:34:59,820::guestIF::278::vm.Vm::(desktopLock) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::desktopLock called
>Thread-1314::DEBUG::2014-02-18 14:34:59,820::guestIF::278::vm.Vm::(desktopLock) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::desktopLock called
>Thread-1315::DEBUG::2014-02-18 14:34:59,820::guestIF::278::vm.Vm::(desktopLock) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::desktopLock called
>Thread-1316::DEBUG::2014-02-18 14:34:59,821::guestIF::278::vm.Vm::(desktopLock) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::desktopLock called
>Thread-153::DEBUG::2014-02-18 14:35:01,664::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.199:_cmg02/227ac6ed-39b0-4e18-a007-7dc7180b4905/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-153::DEBUG::2014-02-18 14:35:01,669::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n451 bytes (451 B) copied, 0.00036732 s, 1.2 MB/s\n'; <rc> = 0
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:02,560::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:02,561::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:02,561::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc latency not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:02,561::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda latency not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:02,562::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:02,562::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:02,562::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc latency not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:02,562::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda latency not available
>Thread-1321::DEBUG::2014-02-18 14:35:06,424::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25]
>Thread-1321::INFO::2014-02-18 14:35:06,425::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-1321::INFO::2014-02-18 14:35:06,437::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 2L}}
>Thread-1322::DEBUG::2014-02-18 14:35:06,441::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25]
>Thread-1322::INFO::2014-02-18 14:35:06,441::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-1322::INFO::2014-02-18 14:35:06,443::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '227ac6ed-39b0-4e18-a007-7dc7180b4905:Active', 'master_uuid': '227ac6ed-39b0-4e18-a007-7dc7180b4905', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'227ac6ed-39b0-4e18-a007-7dc7180b4905': {'status': 'Active', 'diskfree': '142286946304', 'isoprefix': '', 'alerts': [], 'disktotal': '144349954048', 'version': 3}}}
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:07,568::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:07,568::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:07,569::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc latency not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:07,569::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda latency not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:07,569::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:07,570::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:07,570::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc latency not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:07,570::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda latency not available
>Thread-153::DEBUG::2014-02-18 14:35:11,675::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.199:_cmg02/227ac6ed-39b0-4e18-a007-7dc7180b4905/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-153::DEBUG::2014-02-18 14:35:11,679::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n451 bytes (451 B) copied, 0.000344943 s, 1.3 MB/s\n'; <rc> = 0
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:12,576::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:12,576::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:12,577::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc latency not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:12,577::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda latency not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:12,578::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:12,578::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:12,578::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc latency not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:12,579::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda latency not available
>Thread-1325::DEBUG::2014-02-18 14:35:14,088::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25]
>Thread-1325::INFO::2014-02-18 14:35:14,088::logUtils::44::dispatcher::(wrapper) Run and protect: getDeviceList(storageType=3, options={})
>Thread-1325::DEBUG::2014-02-18 14:35:14,089::iscsi::393::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
>Thread-1325::DEBUG::2014-02-18 14:35:14,089::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
>Thread-1325::DEBUG::2014-02-18 14:35:14,102::multipath::110::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath -r' (cwd None)
>Thread-1325::DEBUG::2014-02-18 14:35:14,236::multipath::110::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
>Thread-1325::DEBUG::2014-02-18 14:35:14,238::lvm::295::Storage.Misc.excCmd::(cmd) '/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 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/1cmg01|/dev/mapper/1cmg02|\', \'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)
>Thread-1325::DEBUG::2014-02-18 14:35:14,363::lvm::295::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-1325::DEBUG::2014-02-18 14:35:14,404::lvm::295::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm pvcreate --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/1cmg01|/dev/mapper/1cmg02|\', \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1 }  backup {  retain_min = 50  retain_days = 0 } " --test --metadatasize 128m --metadatacopies 2 --metadataignore y /dev/mapper/1cmg02 /dev/mapper/1cmg01' (cwd None)
>Thread-1326::INFO::2014-02-18 14:35:14,475::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-1326::INFO::2014-02-18 14:35:14,475::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'227ac6ed-39b0-4e18-a007-7dc7180b4905': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000344943', 'lastCheck': '2.8', 'valid': True}}
>Thread-1327::DEBUG::2014-02-18 14:35:14,504::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc stats not available
>Thread-1327::DEBUG::2014-02-18 14:35:14,504::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda stats not available
>Thread-1327::DEBUG::2014-02-18 14:35:14,504::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc latency not available
>Thread-1327::DEBUG::2014-02-18 14:35:14,504::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda latency not available
>Thread-1325::DEBUG::2014-02-18 14:35:14,510::lvm::295::Storage.Misc.excCmd::(cmd) FAILED: <err> = '  TEST MODE: Metadata will NOT be updated and volumes will not be (de)activated.\n  Can\'t open /dev/mapper/1cmg02 exclusively.  Mounted filesystem?\n  Can\'t initialize physical volume "/dev/mapper/1cmg01" of volume group "afcb2944-8c5d-4d60-af6b-d95db3e904ac" without -ff\n'; <rc> = 5
>Thread-1325::DEBUG::2014-02-18 14:35:14,510::lvm::859::Storage.LVM::(testPVCreate) rc: 5, out: [], err: ['  TEST MODE: Metadata will NOT be updated and volumes will not be (de)activated.', "  Can't open /dev/mapper/1cmg02 exclusively.  Mounted filesystem?", '  Can\'t initialize physical volume "/dev/mapper/1cmg01" of volume group "afcb2944-8c5d-4d60-af6b-d95db3e904ac" without -ff'], unusedDevs: set([]), usedDevs: set(['/dev/mapper/1cmg01', '/dev/mapper/1cmg02'])
>Thread-1325::INFO::2014-02-18 14:35:14,511::logUtils::47::dispatcher::(wrapper) Run and protect: getDeviceList, Return response: {'devList': [{'status': 'used', 'vendorID': 'RH-str01', 'capacity': '102005473280', 'fwrev': '0001', 'vgUUID': '', 'pathlist': [{'initiatorname': 'default', 'connection': '10.34.63.202', 'iqn': 'iqn.2012-10.brq.str-01:cmestreg', 'portal': '1', 'password': '******', 'port': '3260'}], 'logicalblocksize': '512', 'pathstatus': [{'physdev': 'sdc', 'type': 'iSCSI', 'state': 'active', 'lun': '2'}], 'devtype': 'iSCSI', 'physicalblocksize': '512', 'pvUUID': '', 'serial': 'SRH-str01VIRTUAL-DISK', 'GUID': '1cmg02', 'productID': 'VIRTUAL-DISK'}, {'status': 'used', 'vendorID': 'RH-str01', 'capacity': '91268055040', 'fwrev': '0001', 'vgUUID': '7rK0aV-n9qX-9br8-PZ2F-L3lO-iv3q-zwhGqH', 'pathlist': [{'initiatorname': 'default', 'connection': '10.34.63.202', 'iqn': 'iqn.2012-10.brq.str-01:cmestreg', 'portal': '1', 'password': '******', 'port': '3260'}], 'logicalblocksize': '512', 'pathstatus': [{'physdev': 'sdb', 'type': 'iSCSI', 'state': 'active', 'lun': '1'}], 'devtype': 'iSCSI', 'physicalblocksize': '512', 'pvUUID': 'Jodqx0-Fee5-QHT0-MeQ3-eIfO-5tWD-N3JCsw', 'serial': 'SRH-str01VIRTUAL-DISK', 'GUID': '1cmg01', 'productID': 'VIRTUAL-DISK'}]}
>Thread-1328::DEBUG::2014-02-18 14:35:16,504::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25] flowID [6bab5b13]
>Thread-1328::INFO::2014-02-18 14:35:16,504::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-1328::INFO::2014-02-18 14:35:16,516::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 2L}}
>Thread-1329::DEBUG::2014-02-18 14:35:16,524::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25] flowID [6bab5b13]
>Thread-1329::INFO::2014-02-18 14:35:16,525::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-1329::INFO::2014-02-18 14:35:16,527::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '227ac6ed-39b0-4e18-a007-7dc7180b4905:Active', 'master_uuid': '227ac6ed-39b0-4e18-a007-7dc7180b4905', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'227ac6ed-39b0-4e18-a007-7dc7180b4905': {'status': 'Active', 'diskfree': '142286946304', 'isoprefix': '', 'alerts': [], 'disktotal': '144349954048', 'version': 3}}}
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:17,584::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:17,585::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:17,585::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc latency not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:17,585::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda latency not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:17,586::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:17,586::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:17,586::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc latency not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:17,586::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda latency not available
>Thread-153::DEBUG::2014-02-18 14:35:21,686::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.199:_cmg02/227ac6ed-39b0-4e18-a007-7dc7180b4905/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-153::DEBUG::2014-02-18 14:35:21,690::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n451 bytes (451 B) copied, 0.000380355 s, 1.2 MB/s\n'; <rc> = 0
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:22,592::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:22,592::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:22,592::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc latency not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:22,592::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda latency not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:22,593::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:22,593::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:22,593::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc latency not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:22,593::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda latency not available
>Thread-1333::DEBUG::2014-02-18 14:35:26,598::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25]
>Thread-1333::INFO::2014-02-18 14:35:26,602::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-1333::INFO::2014-02-18 14:35:26,613::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 2L}}
>Thread-1334::DEBUG::2014-02-18 14:35:26,618::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25]
>Thread-1334::INFO::2014-02-18 14:35:26,618::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-1334::INFO::2014-02-18 14:35:26,640::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '227ac6ed-39b0-4e18-a007-7dc7180b4905:Active', 'master_uuid': '227ac6ed-39b0-4e18-a007-7dc7180b4905', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'227ac6ed-39b0-4e18-a007-7dc7180b4905': {'status': 'Active', 'diskfree': '142286946304', 'isoprefix': '', 'alerts': [], 'disktotal': '144349954048', 'version': 3}}}
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:27,599::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:27,599::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:27,600::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc latency not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:27,600::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda latency not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:27,600::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:27,601::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:27,601::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc latency not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:27,601::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda latency not available
>Thread-1336::INFO::2014-02-18 14:35:29,735::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-1336::INFO::2014-02-18 14:35:29,735::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'227ac6ed-39b0-4e18-a007-7dc7180b4905': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000380355', 'lastCheck': '8.0', 'valid': True}}
>Thread-1337::DEBUG::2014-02-18 14:35:29,777::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc stats not available
>Thread-1337::DEBUG::2014-02-18 14:35:29,777::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda stats not available
>Thread-1337::DEBUG::2014-02-18 14:35:29,777::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc latency not available
>Thread-1337::DEBUG::2014-02-18 14:35:29,778::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda latency not available
>Thread-153::DEBUG::2014-02-18 14:35:31,699::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.199:_cmg02/227ac6ed-39b0-4e18-a007-7dc7180b4905/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-153::DEBUG::2014-02-18 14:35:31,704::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n451 bytes (451 B) copied, 0.000320907 s, 1.4 MB/s\n'; <rc> = 0
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:32,607::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:32,607::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:32,607::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc latency not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:32,607::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda latency not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:32,608::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:32,608::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:32,608::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc latency not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:32,608::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda latency not available
>Thread-1339::DEBUG::2014-02-18 14:35:35,283::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25]
>Thread-1339::INFO::2014-02-18 14:35:35,283::logUtils::44::dispatcher::(wrapper) Run and protect: getDeviceList(storageType=3, options={})
>Thread-1339::DEBUG::2014-02-18 14:35:35,284::iscsi::393::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
>Thread-1339::DEBUG::2014-02-18 14:35:35,284::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
>Thread-1339::DEBUG::2014-02-18 14:35:35,299::multipath::110::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath -r' (cwd None)
>Thread-1339::DEBUG::2014-02-18 14:35:35,416::multipath::110::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
>Thread-1339::DEBUG::2014-02-18 14:35:35,418::lvm::295::Storage.Misc.excCmd::(cmd) '/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 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/1cmg01|/dev/mapper/1cmg02|\', \'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)
>Thread-1339::DEBUG::2014-02-18 14:35:35,536::lvm::295::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-1339::DEBUG::2014-02-18 14:35:35,567::lvm::295::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm pvcreate --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/1cmg01|/dev/mapper/1cmg02|\', \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1 }  backup {  retain_min = 50  retain_days = 0 } " --test --metadatasize 128m --metadatacopies 2 --metadataignore y /dev/mapper/1cmg02 /dev/mapper/1cmg01' (cwd None)
>Thread-1339::DEBUG::2014-02-18 14:35:35,677::lvm::295::Storage.Misc.excCmd::(cmd) FAILED: <err> = '  TEST MODE: Metadata will NOT be updated and volumes will not be (de)activated.\n  Can\'t open /dev/mapper/1cmg02 exclusively.  Mounted filesystem?\n  Can\'t initialize physical volume "/dev/mapper/1cmg01" of volume group "afcb2944-8c5d-4d60-af6b-d95db3e904ac" without -ff\n'; <rc> = 5
>Thread-1339::DEBUG::2014-02-18 14:35:35,677::lvm::859::Storage.LVM::(testPVCreate) rc: 5, out: [], err: ['  TEST MODE: Metadata will NOT be updated and volumes will not be (de)activated.', "  Can't open /dev/mapper/1cmg02 exclusively.  Mounted filesystem?", '  Can\'t initialize physical volume "/dev/mapper/1cmg01" of volume group "afcb2944-8c5d-4d60-af6b-d95db3e904ac" without -ff'], unusedDevs: set([]), usedDevs: set(['/dev/mapper/1cmg01', '/dev/mapper/1cmg02'])
>Thread-1339::INFO::2014-02-18 14:35:35,678::logUtils::47::dispatcher::(wrapper) Run and protect: getDeviceList, Return response: {'devList': [{'status': 'used', 'vendorID': 'RH-str01', 'capacity': '102005473280', 'fwrev': '0001', 'vgUUID': '', 'pathlist': [{'initiatorname': 'default', 'connection': '10.34.63.202', 'iqn': 'iqn.2012-10.brq.str-01:cmestreg', 'portal': '1', 'password': '******', 'port': '3260'}], 'logicalblocksize': '512', 'pathstatus': [{'physdev': 'sdc', 'type': 'iSCSI', 'state': 'active', 'lun': '2'}], 'devtype': 'iSCSI', 'physicalblocksize': '512', 'pvUUID': '', 'serial': 'SRH-str01VIRTUAL-DISK', 'GUID': '1cmg02', 'productID': 'VIRTUAL-DISK'}, {'status': 'used', 'vendorID': 'RH-str01', 'capacity': '91268055040', 'fwrev': '0001', 'vgUUID': '7rK0aV-n9qX-9br8-PZ2F-L3lO-iv3q-zwhGqH', 'pathlist': [{'initiatorname': 'default', 'connection': '10.34.63.202', 'iqn': 'iqn.2012-10.brq.str-01:cmestreg', 'portal': '1', 'password': '******', 'port': '3260'}], 'logicalblocksize': '512', 'pathstatus': [{'physdev': 'sdb', 'type': 'iSCSI', 'state': 'active', 'lun': '1'}], 'devtype': 'iSCSI', 'physicalblocksize': '512', 'pvUUID': 'Jodqx0-Fee5-QHT0-MeQ3-eIfO-5tWD-N3JCsw', 'serial': 'SRH-str01VIRTUAL-DISK', 'GUID': '1cmg01', 'productID': 'VIRTUAL-DISK'}]}
>Thread-1340::DEBUG::2014-02-18 14:35:35,863::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25]
>Thread-1340::INFO::2014-02-18 14:35:35,864::logUtils::44::dispatcher::(wrapper) Run and protect: getDeviceList(storageType=3, options={})
>Thread-1340::DEBUG::2014-02-18 14:35:35,864::iscsi::393::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
>Thread-1340::DEBUG::2014-02-18 14:35:35,864::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
>Thread-1340::DEBUG::2014-02-18 14:35:35,876::multipath::110::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath -r' (cwd None)
>Thread-1340::DEBUG::2014-02-18 14:35:35,990::multipath::110::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
>Thread-1340::DEBUG::2014-02-18 14:35:35,992::lvm::295::Storage.Misc.excCmd::(cmd) '/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 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/1cmg01|/dev/mapper/1cmg02|\', \'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)
>Thread-1340::DEBUG::2014-02-18 14:35:36,100::lvm::295::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-1340::DEBUG::2014-02-18 14:35:36,116::lvm::295::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm pvcreate --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/1cmg01|/dev/mapper/1cmg02|\', \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1 }  backup {  retain_min = 50  retain_days = 0 } " --test --metadatasize 128m --metadatacopies 2 --metadataignore y /dev/mapper/1cmg02 /dev/mapper/1cmg01' (cwd None)
>Thread-1340::DEBUG::2014-02-18 14:35:36,219::lvm::295::Storage.Misc.excCmd::(cmd) FAILED: <err> = '  TEST MODE: Metadata will NOT be updated and volumes will not be (de)activated.\n  Can\'t open /dev/mapper/1cmg02 exclusively.  Mounted filesystem?\n  Can\'t initialize physical volume "/dev/mapper/1cmg01" of volume group "afcb2944-8c5d-4d60-af6b-d95db3e904ac" without -ff\n'; <rc> = 5
>Thread-1340::DEBUG::2014-02-18 14:35:36,220::lvm::859::Storage.LVM::(testPVCreate) rc: 5, out: [], err: ['  TEST MODE: Metadata will NOT be updated and volumes will not be (de)activated.', "  Can't open /dev/mapper/1cmg02 exclusively.  Mounted filesystem?", '  Can\'t initialize physical volume "/dev/mapper/1cmg01" of volume group "afcb2944-8c5d-4d60-af6b-d95db3e904ac" without -ff'], unusedDevs: set([]), usedDevs: set(['/dev/mapper/1cmg01', '/dev/mapper/1cmg02'])
>Thread-1340::INFO::2014-02-18 14:35:36,220::logUtils::47::dispatcher::(wrapper) Run and protect: getDeviceList, Return response: {'devList': [{'status': 'used', 'vendorID': 'RH-str01', 'capacity': '102005473280', 'fwrev': '0001', 'vgUUID': '', 'pathlist': [{'initiatorname': 'default', 'connection': '10.34.63.202', 'iqn': 'iqn.2012-10.brq.str-01:cmestreg', 'portal': '1', 'password': '******', 'port': '3260'}], 'logicalblocksize': '512', 'pathstatus': [{'physdev': 'sdc', 'type': 'iSCSI', 'state': 'active', 'lun': '2'}], 'devtype': 'iSCSI', 'physicalblocksize': '512', 'pvUUID': '', 'serial': 'SRH-str01VIRTUAL-DISK', 'GUID': '1cmg02', 'productID': 'VIRTUAL-DISK'}, {'status': 'used', 'vendorID': 'RH-str01', 'capacity': '91268055040', 'fwrev': '0001', 'vgUUID': '7rK0aV-n9qX-9br8-PZ2F-L3lO-iv3q-zwhGqH', 'pathlist': [{'initiatorname': 'default', 'connection': '10.34.63.202', 'iqn': 'iqn.2012-10.brq.str-01:cmestreg', 'portal': '1', 'password': '******', 'port': '3260'}], 'logicalblocksize': '512', 'pathstatus': [{'physdev': 'sdb', 'type': 'iSCSI', 'state': 'active', 'lun': '1'}], 'devtype': 'iSCSI', 'physicalblocksize': '512', 'pvUUID': 'Jodqx0-Fee5-QHT0-MeQ3-eIfO-5tWD-N3JCsw', 'serial': 'SRH-str01VIRTUAL-DISK', 'GUID': '1cmg01', 'productID': 'VIRTUAL-DISK'}]}
>Thread-1342::DEBUG::2014-02-18 14:35:36,679::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25]
>Thread-1342::INFO::2014-02-18 14:35:36,680::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-1342::INFO::2014-02-18 14:35:36,692::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 2L}}
>Thread-1343::DEBUG::2014-02-18 14:35:36,697::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25]
>Thread-1343::INFO::2014-02-18 14:35:36,697::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-1343::INFO::2014-02-18 14:35:36,700::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '227ac6ed-39b0-4e18-a007-7dc7180b4905:Active', 'master_uuid': '227ac6ed-39b0-4e18-a007-7dc7180b4905', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'227ac6ed-39b0-4e18-a007-7dc7180b4905': {'status': 'Active', 'diskfree': '142286946304', 'isoprefix': '', 'alerts': [], 'disktotal': '144349954048', 'version': 3}}}
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:37,614::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:37,614::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:37,614::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc latency not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:37,614::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda latency not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:37,620::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:37,621::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:37,621::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk hdc latency not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:35:37,621::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vda latency not available
>Thread-1345::DEBUG::2014-02-18 14:35:41,421::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25]
>Thread-1345::INFO::2014-02-18 14:35:41,421::logUtils::44::dispatcher::(wrapper) Run and protect: getDeviceList(storageType=3, options={})
>Thread-1345::DEBUG::2014-02-18 14:35:41,421::iscsi::393::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
>Thread-1345::DEBUG::2014-02-18 14:35:41,421::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
>Thread-1345::DEBUG::2014-02-18 14:35:41,433::multipath::110::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath -r' (cwd None)
>Thread-1345::DEBUG::2014-02-18 14:35:41,531::multipath::110::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
>Thread-1345::DEBUG::2014-02-18 14:35:41,534::lvm::295::Storage.Misc.excCmd::(cmd) '/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 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/1cmg01|/dev/mapper/1cmg02|\', \'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)
>Thread-1345::DEBUG::2014-02-18 14:35:41,649::lvm::295::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-1345::DEBUG::2014-02-18 14:35:41,676::lvm::295::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm pvcreate --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/1cmg01|/dev/mapper/1cmg02|\', \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1 }  backup {  retain_min = 50  retain_days = 0 } " --test --metadatasize 128m --metadatacopies 2 --metadataignore y /dev/mapper/1cmg02 /dev/mapper/1cmg01' (cwd None)
>Thread-153::DEBUG::2014-02-18 14:35:41,714::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.199:_cmg02/227ac6ed-39b0-4e18-a007-7dc7180b4905/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-153::DEBUG::2014-02-18 14:35:41,719::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n451 bytes (451 B) copied, 0.000327538 s, 1.4 MB/s\n'; <rc> = 0
>Thread-1345::DEBUG::2014-02-18 14:35:41,783::lvm::295::Storage.Misc.excCmd::(cmd) FAILED: <err> = '  TEST MODE: Metadata will NOT be updated and volumes will not be (de)activated.\n  Can\'t open /dev/mapper/1cmg02 exclusively.  Mounted filesystem?\n  Can\'t initialize physical volume "/dev/mapper/1cmg01" of volume group "afcb2944-8c5d-4d60-af6b-d95db3e904ac" without -ff\n'; <rc> = 5
>Thread-1345::DEBUG::2014-02-18 14:35:41,784::lvm::859::Storage.LVM::(testPVCreate) rc: 5, out: [], err: ['  TEST MODE: Metadata will NOT be updated and volumes will not be (de)activated.', "  Can't open /dev/mapper/1cmg02 exclusively.  Mounted filesystem?", '  Can\'t initialize physical volume "/dev/mapper/1cmg01" of volume group "afcb2944-8c5d-4d60-af6b-d95db3e904ac" without -ff'], unusedDevs: set([]), usedDevs: set(['/dev/mapper/1cmg01', '/dev/mapper/1cmg02'])
>Thread-1345::INFO::2014-02-18 14:35:41,785::logUtils::47::dispatcher::(wrapper) Run and protect: getDeviceList, Return response: {'devList': [{'status': 'used', 'vendorID': 'RH-str01', 'capacity': '102005473280', 'fwrev': '0001', 'vgUUID': '', 'pathlist': [{'initiatorname': 'default', 'connection': '10.34.63.202', 'iqn': 'iqn.2012-10.brq.str-01:cmestreg', 'portal': '1', 'password': '******', 'port': '3260'}], 'logicalblocksize': '512', 'pathstatus': [{'physdev': 'sdc', 'type': 'iSCSI', 'state': 'active', 'lun': '2'}], 'devtype': 'iSCSI', 'physicalblocksize': '512', 'pvUUID': '', 'serial': 'SRH-str01VIRTUAL-DISK', 'GUID': '1cmg02', 'productID': 'VIRTUAL-DISK'}, {'status': 'used', 'vendorID': 'RH-str01', 'capacity': '91268055040', 'fwrev': '0001', 'vgUUID': '7rK0aV-n9qX-9br8-PZ2F-L3lO-iv3q-zwhGqH', 'pathlist': [{'initiatorname': 'default', 'connection': '10.34.63.202', 'iqn': 'iqn.2012-10.brq.str-01:cmestreg', 'portal': '1', 'password': '******', 'port': '3260'}], 'logicalblocksize': '512', 'pathstatus': [{'physdev': 'sdb', 'type': 'iSCSI', 'state': 'active', 'lun': '1'}], 'devtype': 'iSCSI', 'physicalblocksize': '512', 'pvUUID': 'Jodqx0-Fee5-QHT0-MeQ3-eIfO-5tWD-N3JCsw', 'serial': 'SRH-str01VIRTUAL-DISK', 'GUID': '1cmg01', 'productID': 'VIRTUAL-DISK'}]}
>Thread-1347::INFO::2014-02-18 14:35:45,092::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-1347::INFO::2014-02-18 14:35:45,092::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'227ac6ed-39b0-4e18-a007-7dc7180b4905': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000327538', 'lastCheck': '3.4', 'valid': True}}
>Thread-1349::DEBUG::2014-02-18 14:35:46,782::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25]
>Thread-1349::INFO::2014-02-18 14:35:46,784::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-1349::INFO::2014-02-18 14:35:46,796::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 2L}}
>Thread-1350::DEBUG::2014-02-18 14:35:46,801::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25]
>Thread-1350::INFO::2014-02-18 14:35:46,801::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-1350::INFO::2014-02-18 14:35:46,803::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '227ac6ed-39b0-4e18-a007-7dc7180b4905:Active', 'master_uuid': '227ac6ed-39b0-4e18-a007-7dc7180b4905', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'227ac6ed-39b0-4e18-a007-7dc7180b4905': {'status': 'Active', 'diskfree': '142286946304', 'isoprefix': '', 'alerts': [], 'disktotal': '144349954048', 'version': 3}}}
>Thread-153::DEBUG::2014-02-18 14:35:51,741::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.199:_cmg02/227ac6ed-39b0-4e18-a007-7dc7180b4905/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-153::DEBUG::2014-02-18 14:35:51,749::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n451 bytes (451 B) copied, 0.000584765 s, 771 kB/s\n'; <rc> = 0
>Thread-1354::DEBUG::2014-02-18 14:35:56,843::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25]
>Thread-1354::INFO::2014-02-18 14:35:56,843::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-1354::INFO::2014-02-18 14:35:56,855::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 2L}}
>Thread-1355::DEBUG::2014-02-18 14:35:56,859::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25]
>Thread-1355::INFO::2014-02-18 14:35:56,860::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-1355::INFO::2014-02-18 14:35:56,862::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '227ac6ed-39b0-4e18-a007-7dc7180b4905:Active', 'master_uuid': '227ac6ed-39b0-4e18-a007-7dc7180b4905', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'227ac6ed-39b0-4e18-a007-7dc7180b4905': {'status': 'Active', 'diskfree': '142286946304', 'isoprefix': '', 'alerts': [], 'disktotal': '144349954048', 'version': 3}}}
>Thread-1357::INFO::2014-02-18 14:36:00,253::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-1357::INFO::2014-02-18 14:36:00,253::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'227ac6ed-39b0-4e18-a007-7dc7180b4905': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000584765', 'lastCheck': '8.5', 'valid': True}}
>Thread-1359::DEBUG::2014-02-18 14:36:01,254::BindingXMLRPC::970::vds::(wrapper) client [10.34.63.25]::call vmSetTicket with ('1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f', '/ZKl1OlkvhXW', '120', 'disconnect', {'userName': 'admin', 'userId': 'fdfc627c-d875-11e0-90f0-83df133b58cc'}) {} flowID [56cba188]
>Thread-1359::DEBUG::2014-02-18 14:36:01,301::BindingXMLRPC::977::vds::(wrapper) return vmSetTicket with {'status': {'message': 'Done', 'code': 0}}
>Thread-153::DEBUG::2014-02-18 14:36:01,759::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.199:_cmg02/227ac6ed-39b0-4e18-a007-7dc7180b4905/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-153::DEBUG::2014-02-18 14:36:01,763::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n451 bytes (451 B) copied, 0.000381609 s, 1.2 MB/s\n'; <rc> = 0
>libvirtEventLoop::DEBUG::2014-02-18 14:36:04,681::clientIF::550::vm.Vm::(dispatchLibvirtEvents) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::graphics event phase 0 localAddr {'node': '10.34.62.206', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.114', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2014-02-18 14:36:04,695::clientIF::550::vm.Vm::(dispatchLibvirtEvents) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::graphics event phase 1 localAddr {'node': '10.34.62.206', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.114', 'service': '', 'family': 0}authScheme spice subject []
>libvirtEventLoop::DEBUG::2014-02-18 14:36:04,744::clientIF::550::vm.Vm::(dispatchLibvirtEvents) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::graphics event phase 0 localAddr {'node': '10.34.62.206', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.114', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2014-02-18 14:36:04,761::clientIF::550::vm.Vm::(dispatchLibvirtEvents) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::graphics event phase 1 localAddr {'node': '10.34.62.206', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.114', 'service': '', 'family': 0}authScheme spice subject []
>libvirtEventLoop::DEBUG::2014-02-18 14:36:04,823::clientIF::550::vm.Vm::(dispatchLibvirtEvents) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::graphics event phase 0 localAddr {'node': '10.34.62.206', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.114', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2014-02-18 14:36:04,823::clientIF::550::vm.Vm::(dispatchLibvirtEvents) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::graphics event phase 0 localAddr {'node': '10.34.62.206', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.114', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2014-02-18 14:36:04,841::clientIF::550::vm.Vm::(dispatchLibvirtEvents) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::graphics event phase 1 localAddr {'node': '10.34.62.206', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.114', 'service': '', 'family': 0}authScheme spice subject []
>libvirtEventLoop::DEBUG::2014-02-18 14:36:04,842::clientIF::550::vm.Vm::(dispatchLibvirtEvents) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::graphics event phase 1 localAddr {'node': '10.34.62.206', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.114', 'service': '', 'family': 0}authScheme spice subject []
>libvirtEventLoop::DEBUG::2014-02-18 14:36:06,630::clientIF::550::vm.Vm::(dispatchLibvirtEvents) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::graphics event phase 2 localAddr {'node': '10.34.62.206', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.114', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2014-02-18 14:36:06,631::clientIF::550::vm.Vm::(dispatchLibvirtEvents) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::graphics event phase 2 localAddr {'node': '10.34.62.206', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.114', 'service': '', 'family': 0}authScheme spice subject []
>libvirtEventLoop::DEBUG::2014-02-18 14:36:06,631::clientIF::550::vm.Vm::(dispatchLibvirtEvents) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::graphics event phase 2 localAddr {'node': '10.34.62.206', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.114', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2014-02-18 14:36:06,632::clientIF::550::vm.Vm::(dispatchLibvirtEvents) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::graphics event phase 2 localAddr {'node': '10.34.62.206', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.114', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2014-02-18 14:36:06,632::clientIF::550::vm.Vm::(dispatchLibvirtEvents) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::graphics event phase 2 localAddr {'node': '10.34.62.206', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.114', 'service': '', 'family': 0}authScheme  subject []
>Thread-1367::DEBUG::2014-02-18 14:36:06,926::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25]
>Thread-1367::INFO::2014-02-18 14:36:06,926::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-1367::INFO::2014-02-18 14:36:06,938::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 2L}}
>Thread-1368::DEBUG::2014-02-18 14:36:06,943::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25]
>Thread-1368::INFO::2014-02-18 14:36:06,943::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-1368::INFO::2014-02-18 14:36:06,945::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '227ac6ed-39b0-4e18-a007-7dc7180b4905:Active', 'master_uuid': '227ac6ed-39b0-4e18-a007-7dc7180b4905', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'227ac6ed-39b0-4e18-a007-7dc7180b4905': {'status': 'Active', 'diskfree': '142286946304', 'isoprefix': '', 'alerts': [], 'disktotal': '144349954048', 'version': 3}}}
>Thread-1362::DEBUG::2014-02-18 14:36:08,631::guestIF::278::vm.Vm::(desktopLock) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::desktopLock called
>Thread-1363::DEBUG::2014-02-18 14:36:08,631::guestIF::278::vm.Vm::(desktopLock) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::desktopLock called
>Thread-1364::DEBUG::2014-02-18 14:36:08,631::guestIF::278::vm.Vm::(desktopLock) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::desktopLock called
>Thread-1365::DEBUG::2014-02-18 14:36:08,632::guestIF::278::vm.Vm::(desktopLock) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::desktopLock called
>Thread-1366::DEBUG::2014-02-18 14:36:08,632::guestIF::278::vm.Vm::(desktopLock) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::desktopLock called
>Thread-153::DEBUG::2014-02-18 14:36:11,770::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.199:_cmg02/227ac6ed-39b0-4e18-a007-7dc7180b4905/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-153::DEBUG::2014-02-18 14:36:11,774::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n451 bytes (451 B) copied, 0.000359594 s, 1.3 MB/s\n'; <rc> = 0
>Thread-1371::DEBUG::2014-02-18 14:36:15,130::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25]
>Thread-1371::INFO::2014-02-18 14:36:15,130::logUtils::44::dispatcher::(wrapper) Run and protect: getDeviceList(storageType=3, options={})
>Thread-1371::DEBUG::2014-02-18 14:36:15,130::iscsi::393::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
>Thread-1371::DEBUG::2014-02-18 14:36:15,131::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
>Thread-1371::DEBUG::2014-02-18 14:36:15,146::multipath::110::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath -r' (cwd None)
>Thread-1371::DEBUG::2014-02-18 14:36:15,269::multipath::110::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
>Thread-1371::DEBUG::2014-02-18 14:36:15,272::lvm::295::Storage.Misc.excCmd::(cmd) '/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 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/1cmg01|/dev/mapper/1cmg02|\', \'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)
>Thread-1371::DEBUG::2014-02-18 14:36:15,390::lvm::295::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-1371::DEBUG::2014-02-18 14:36:15,420::lvm::295::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm pvcreate --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/1cmg01|/dev/mapper/1cmg02|\', \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1 }  backup {  retain_min = 50  retain_days = 0 } " --test --metadatasize 128m --metadatacopies 2 --metadataignore y /dev/mapper/1cmg02 /dev/mapper/1cmg01' (cwd None)
>Thread-1372::INFO::2014-02-18 14:36:15,478::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-1372::INFO::2014-02-18 14:36:15,478::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'227ac6ed-39b0-4e18-a007-7dc7180b4905': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000359594', 'lastCheck': '3.7', 'valid': True}}
>Thread-1371::DEBUG::2014-02-18 14:36:15,529::lvm::295::Storage.Misc.excCmd::(cmd) FAILED: <err> = '  TEST MODE: Metadata will NOT be updated and volumes will not be (de)activated.\n  Can\'t open /dev/mapper/1cmg02 exclusively.  Mounted filesystem?\n  Can\'t initialize physical volume "/dev/mapper/1cmg01" of volume group "afcb2944-8c5d-4d60-af6b-d95db3e904ac" without -ff\n'; <rc> = 5
>Thread-1371::DEBUG::2014-02-18 14:36:15,530::lvm::859::Storage.LVM::(testPVCreate) rc: 5, out: [], err: ['  TEST MODE: Metadata will NOT be updated and volumes will not be (de)activated.', "  Can't open /dev/mapper/1cmg02 exclusively.  Mounted filesystem?", '  Can\'t initialize physical volume "/dev/mapper/1cmg01" of volume group "afcb2944-8c5d-4d60-af6b-d95db3e904ac" without -ff'], unusedDevs: set([]), usedDevs: set(['/dev/mapper/1cmg01', '/dev/mapper/1cmg02'])
>Thread-1371::INFO::2014-02-18 14:36:15,530::logUtils::47::dispatcher::(wrapper) Run and protect: getDeviceList, Return response: {'devList': [{'status': 'used', 'vendorID': 'RH-str01', 'capacity': '102005473280', 'fwrev': '0001', 'vgUUID': '', 'pathlist': [{'initiatorname': 'default', 'connection': '10.34.63.202', 'iqn': 'iqn.2012-10.brq.str-01:cmestreg', 'portal': '1', 'password': '******', 'port': '3260'}], 'logicalblocksize': '512', 'pathstatus': [{'physdev': 'sdc', 'type': 'iSCSI', 'state': 'active', 'lun': '2'}], 'devtype': 'iSCSI', 'physicalblocksize': '512', 'pvUUID': '', 'serial': 'SRH-str01VIRTUAL-DISK', 'GUID': '1cmg02', 'productID': 'VIRTUAL-DISK'}, {'status': 'used', 'vendorID': 'RH-str01', 'capacity': '91268055040', 'fwrev': '0001', 'vgUUID': '7rK0aV-n9qX-9br8-PZ2F-L3lO-iv3q-zwhGqH', 'pathlist': [{'initiatorname': 'default', 'connection': '10.34.63.202', 'iqn': 'iqn.2012-10.brq.str-01:cmestreg', 'portal': '1', 'password': '******', 'port': '3260'}], 'logicalblocksize': '512', 'pathstatus': [{'physdev': 'sdb', 'type': 'iSCSI', 'state': 'active', 'lun': '1'}], 'devtype': 'iSCSI', 'physicalblocksize': '512', 'pvUUID': 'Jodqx0-Fee5-QHT0-MeQ3-eIfO-5tWD-N3JCsw', 'serial': 'SRH-str01VIRTUAL-DISK', 'GUID': '1cmg01', 'productID': 'VIRTUAL-DISK'}]}
>Thread-1374::DEBUG::2014-02-18 14:36:16,972::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25]
>Thread-1374::INFO::2014-02-18 14:36:16,972::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-1374::INFO::2014-02-18 14:36:16,985::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 2L}}
>Thread-1375::DEBUG::2014-02-18 14:36:16,989::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25]
>Thread-1375::INFO::2014-02-18 14:36:16,989::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-1375::INFO::2014-02-18 14:36:16,991::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '227ac6ed-39b0-4e18-a007-7dc7180b4905:Active', 'master_uuid': '227ac6ed-39b0-4e18-a007-7dc7180b4905', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'227ac6ed-39b0-4e18-a007-7dc7180b4905': {'status': 'Active', 'diskfree': '142286946304', 'isoprefix': '', 'alerts': [], 'disktotal': '144349954048', 'version': 3}}}
>Thread-1377::DEBUG::2014-02-18 14:36:18,874::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25] flowID [2c64e35e]
>Thread-1377::INFO::2014-02-18 14:36:18,874::logUtils::44::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=3, spUUID='00000002-0002-0002-0002-000000000002', conList=[{'connection': '10.34.63.202', 'iqn': 'iqn.2012-10.brq.str-01:cmestreg', 'portal': '1', 'user': '', 'password': '******', 'id': 'f7c28cc2-985f-4977-b4b0-f19c30c788da', 'port': '3260'}], options=None)
>Thread-1377::DEBUG::2014-02-18 14:36:18,875::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m node -T iqn.2012-10.brq.str-01:cmestreg -I default -p 10.34.63.202:3260 --op=new' (cwd None)
>Thread-1377::DEBUG::2014-02-18 14:36:18,885::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-1377::DEBUG::2014-02-18 14:36:18,885::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m node -T iqn.2012-10.brq.str-01:cmestreg -I default -p 10.34.63.202:3260 -l' (cwd None)
>Thread-1377::DEBUG::2014-02-18 14:36:18,895::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-1377::DEBUG::2014-02-18 14:36:18,895::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m node -T iqn.2012-10.brq.str-01:cmestreg -I default -p 10.34.63.202:3260 -n node.startup -v manual --op=update' (cwd None)
>Thread-1377::DEBUG::2014-02-18 14:36:18,902::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-1377::DEBUG::2014-02-18 14:36:18,903::lvm::295::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/1cmg01|/dev/mapper/1cmg02|\', \'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,lv_count,pv_count,pv_name' (cwd None)
>Thread-1377::DEBUG::2014-02-18 14:36:19,006::lvm::295::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-1377::DEBUG::2014-02-18 14:36:19,007::hsm::2325::Storage.HSM::(__prefetchDomains) Found SD uuids: ('afcb2944-8c5d-4d60-af6b-d95db3e904ac',)
>Thread-1377::DEBUG::2014-02-18 14:36:19,007::hsm::2381::Storage.HSM::(connectStorageServer) knownSDs: {3f620296-84b7-49f2-bb20-41e68cdadfbc: storage.nfsSD.findDomain, 227ac6ed-39b0-4e18-a007-7dc7180b4905: storage.nfsSD.findDomain, afcb2944-8c5d-4d60-af6b-d95db3e904ac: storage.blockSD.findDomain, 6116a097-264f-40f2-9c37-b0a1d79b1dd2: storage.blockSD.findDomain}
>Thread-1377::INFO::2014-02-18 14:36:19,007::logUtils::47::dispatcher::(wrapper) Run and protect: connectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': 'f7c28cc2-985f-4977-b4b0-f19c30c788da'}]}
>Thread-1378::DEBUG::2014-02-18 14:36:19,018::BindingXMLRPC::970::vds::(wrapper) client [10.34.63.25]::call vmHotplugDisk with ({'vmId': '1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f', 'drive': {'iface': 'virtio', 'format': 'raw', 'type': 'disk', 'readonly': 'false', 'deviceId': 'fa55b738-1dbe-48dc-a0cc-3d4733e3a344', 'propagateErrors': 'off', 'device': 'lun', 'shared': 'false', 'GUID': '1cmg01', 'optional': 'false'}},) {} flowID [2c64e35e]
>Thread-1378::INFO::2014-02-18 14:36:19,018::logUtils::44::dispatcher::(wrapper) Run and protect: getDevicesVisibility(guids=['1cmg01'], options=None)
>Thread-1378::INFO::2014-02-18 14:36:19,018::logUtils::47::dispatcher::(wrapper) Run and protect: getDevicesVisibility, Return response: {'visible': {'1cmg01': True}}
>Thread-1378::INFO::2014-02-18 14:36:19,019::logUtils::44::dispatcher::(wrapper) Run and protect: appropriateDevice(guid='1cmg01', thiefId=None)
>Thread-1378::INFO::2014-02-18 14:36:20,069::logUtils::47::dispatcher::(wrapper) Run and protect: appropriateDevice, Return response: None
>Thread-1378::INFO::2014-02-18 14:36:20,070::clientIF::320::vds::(prepareVolumePath) prepared volume path: /dev/mapper/1cmg01
>Thread-1378::DEBUG::2014-02-18 14:36:20,071::vm::3548::vm.Vm::(hotplugDisk) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Hotplug disk xml: <disk device="lun" snapshot="no" type="block">
>	<source dev="/dev/mapper/1cmg01"/>
>	<target bus="virtio" dev="vdb"/>
>	<serial></serial>
>	<driver cache="none" error_policy="stop" io="native" name="qemu" type="raw"/>
></disk>
>
>Thread-1378::DEBUG::2014-02-18 14:36:20,190::vm::4961::vm.Vm::(_getUnderlyingDriveInfo) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Looking for drive with attributes {'name': u'hdc', 'bootOrder': '', 'boot': [], 'readonly': True, 'address': {u'bus': u'1', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'0'}, 'path': '', 'type': u'cdrom'}
>Thread-1378::DEBUG::2014-02-18 14:36:20,190::vm::4972::vm.Vm::(_getUnderlyingDriveInfo) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Matched {'name': (u'hdc', u'hdc'), 'bootOrder': ('', None), 'boot': ([], None), 'readonly': (True, True), 'address': ({u'bus': u'1', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'0'}, {u'bus': u'1', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'0'}), 'path': ('', ''), 'type': (u'cdrom', u'cdrom')}
>Thread-1378::DEBUG::2014-02-18 14:36:20,190::vm::4983::vm.Vm::(_getUnderlyingDriveInfo) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Matched {'name': (u'hdc', u'hdc'), 'bootOrder': ('', None), 'boot': ([], None), 'readonly': (True, 'True'), 'address': ({u'bus': u'1', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'0'}, {u'bus': u'1', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'0'}), 'path': ('', ''), 'type': (u'cdrom', 'disk')}
>Thread-1378::DEBUG::2014-02-18 14:36:20,190::vm::4961::vm.Vm::(_getUnderlyingDriveInfo) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Looking for drive with attributes {'name': u'vda', 'bootOrder': u'1', 'boot': [<DOM Element: boot at 0x7f1fe46688c0>], 'readonly': False, 'address': {u'slot': u'0x06', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, 'path': u'/dev/mapper/1cmg02', 'type': u'disk'}
>Thread-1378::DEBUG::2014-02-18 14:36:20,190::vm::4972::vm.Vm::(_getUnderlyingDriveInfo) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Matched {'name': (u'vda', u'vda'), 'bootOrder': (u'1', u'1'), 'boot': ([<DOM Element: boot at 0x7f1fe46688c0>], None), 'readonly': (False, False), 'address': ({u'slot': u'0x06', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, {u'slot': u'0x06', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}), 'path': (u'/dev/mapper/1cmg02', '/dev/mapper/1cmg02'), 'type': (u'disk', u'disk')}
>Thread-1378::DEBUG::2014-02-18 14:36:20,190::vm::4983::vm.Vm::(_getUnderlyingDriveInfo) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Matched {'name': (u'vda', u'vda'), 'bootOrder': (u'1', u'1'), 'boot': ([<DOM Element: boot at 0x7f1fe46688c0>], None), 'readonly': (False, 'False'), 'address': ({u'slot': u'0x06', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, {u'slot': u'0x06', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}), 'path': (u'/dev/mapper/1cmg02', '/dev/mapper/1cmg02'), 'type': (u'disk', 'disk')}
>Thread-1378::DEBUG::2014-02-18 14:36:20,191::vm::4961::vm.Vm::(_getUnderlyingDriveInfo) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Looking for drive with attributes {'name': u'vdb', 'bootOrder': '', 'boot': [], 'readonly': False, 'address': {u'slot': u'0x08', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, 'path': u'/dev/mapper/1cmg01', 'type': u'lun'}
>Thread-1378::DEBUG::2014-02-18 14:36:20,191::vm::4972::vm.Vm::(_getUnderlyingDriveInfo) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Matched {'name': (u'vdb', u'vdb'), 'bootOrder': ('', None), 'boot': ([], None), 'readonly': (False, False), 'address': ({u'slot': u'0x08', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, {u'slot': u'0x08', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}), 'path': (u'/dev/mapper/1cmg01', '/dev/mapper/1cmg01'), 'type': (u'lun', u'lun')}
>Thread-1378::DEBUG::2014-02-18 14:36:20,191::vm::4983::vm.Vm::(_getUnderlyingDriveInfo) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Matched {'name': (u'vdb', u'vdb'), 'bootOrder': ('', None), 'boot': ([], None), 'readonly': (False, 'False'), 'address': ({u'slot': u'0x08', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, {u'slot': u'0x08', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}), 'path': (u'/dev/mapper/1cmg01', '/dev/mapper/1cmg01'), 'type': (u'lun', 'disk')}
>Thread-1378::DEBUG::2014-02-18 14:36:20,191::BindingXMLRPC::977::vds::(wrapper) return vmHotplugDisk with {'status': {'message': 'Done', 'code': 0}, 'vmList': {'status': 'Up', 'acpiEnable': 'true', 'emulatedMachine': 'rhel6.5.0', 'vmId': '1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f', 'pid': '663', 'memGuaranteedSize': 1024, 'timeOffset': '0', 'keyboardLayout': 'en-us', 'displayPort': u'5900', 'displaySecurePort': u'5901', 'spiceSslCipherSuite': 'DEFAULT', 'cpuType': 'Penryn', 'custom': {'device_620dc094-2376-4a95-8f44-bb32f655de63device_ddb1bf74-0a4d-4a1d-b81c-75de674b703bdevice_9a5d8b59-ce55-4a64-b473-a9ee5ed06146device_bc18d987-298b-42ce-9108-865c7bef0bc5': 'VmDevice {vmId=1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f, deviceId=bc18d987-298b-42ce-9108-865c7bef0bc5, device=unix, type=CHANNEL, bootOrder=0, specParams={}, address={port=1, bus=0, controller=0, type=virtio-serial}, managed=false, plugged=true, readOnly=false, deviceAlias=channel0, customProperties={}, snapshotId=null}', 'device_620dc094-2376-4a95-8f44-bb32f655de63device_ddb1bf74-0a4d-4a1d-b81c-75de674b703bdevice_9a5d8b59-ce55-4a64-b473-a9ee5ed06146': 'VmDevice {vmId=1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f, deviceId=9a5d8b59-ce55-4a64-b473-a9ee5ed06146, device=virtio-serial, type=CONTROLLER, bootOrder=0, specParams={}, address={bus=0x00, domain=0x0000, type=pci, slot=0x05, function=0x0}, managed=false, plugged=true, readOnly=false, deviceAlias=virtio-serial0, customProperties={}, snapshotId=null}', 'device_620dc094-2376-4a95-8f44-bb32f655de63device_ddb1bf74-0a4d-4a1d-b81c-75de674b703bdevice_9a5d8b59-ce55-4a64-b473-a9ee5ed06146device_bc18d987-298b-42ce-9108-865c7bef0bc5device_15c4273a-bfa6-419e-b166-8cecbf53a017device_4cb71313-c2ac-49c1-bfc1-50ef6211edfe': 'VmDevice {vmId=1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f, deviceId=4cb71313-c2ac-49c1-bfc1-50ef6211edfe, device=spicevmc, type=CHANNEL, bootOrder=0, specParams={}, address={port=3, bus=0, controller=0, type=virtio-serial}, managed=false, plugged=true, readOnly=false, deviceAlias=channel2, customProperties={}, snapshotId=null}', 'device_620dc094-2376-4a95-8f44-bb32f655de63device_ddb1bf74-0a4d-4a1d-b81c-75de674b703bdevice_9a5d8b59-ce55-4a64-b473-a9ee5ed06146device_bc18d987-298b-42ce-9108-865c7bef0bc5device_15c4273a-bfa6-419e-b166-8cecbf53a017': 'VmDevice {vmId=1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f, deviceId=15c4273a-bfa6-419e-b166-8cecbf53a017, device=unix, type=CHANNEL, bootOrder=0, specParams={}, address={port=2, bus=0, controller=0, type=virtio-serial}, managed=false, plugged=true, readOnly=false, deviceAlias=channel1, customProperties={}, snapshotId=null}', 'device_620dc094-2376-4a95-8f44-bb32f655de63device_ddb1bf74-0a4d-4a1d-b81c-75de674b703b': 'VmDevice {vmId=1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f, deviceId=ddb1bf74-0a4d-4a1d-b81c-75de674b703b, device=ide, type=CONTROLLER, bootOrder=0, specParams={}, address={bus=0x00, domain=0x0000, type=pci, slot=0x01, function=0x1}, managed=false, plugged=true, readOnly=false, deviceAlias=ide0, customProperties={}, snapshotId=null}', 'device_620dc094-2376-4a95-8f44-bb32f655de63': 'VmDevice {vmId=1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f, deviceId=620dc094-2376-4a95-8f44-bb32f655de63, device=memballoon, type=BALLOON, bootOrder=0, specParams={model=virtio}, address={bus=0x00, domain=0x0000, type=pci, slot=0x07, function=0x0}, managed=false, plugged=true, readOnly=false, deviceAlias=balloon0, customProperties={}, snapshotId=null}'}, 'pauseCode': 'NOERR', 'clientIp': '', 'nicModel': 'rtl8139,pv', 'smartcardEnable': 'false', 'kvmEnable': 'true', 'transparentHugePages': 'true', 'devices': [{'target': 1048576, 'alias': u'balloon0', 'specParams': {'model': 'virtio'}, 'deviceId': '9f07aed9-1708-48e9-9ccd-0f73ad55f31c', 'address': {u'slot': u'0x07', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, 'device': 'memballoon', 'type': 'balloon'}, {'index': '0', 'alias': u'scsi0', 'specParams': {}, 'deviceId': 'ca73cb06-9d48-4682-9dd1-00e0cb7fad06', 'address': {u'slot': u'0x04', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, 'device': 'scsi', 'model': 'virtio-scsi', 'type': 'controller'}, {'alias': u'video0', 'specParams': {'vram': '32768', 'heads': '1'}, 'deviceId': '5e07330d-5ec3-47d4-b290-f0518cf3d067', 'address': {u'slot': u'0x02', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, 'device': 'qxl', 'type': 'video'}, {'nicModel': 'pv', 'macAddr': '00:1a:4a:30:3f:16', 'linkActive': True, 'network': 'ovirtmgmt', 'alias': u'net0', 'bootOrder': '2', 'filter': 'vdsm-no-mac-spoofing', 'specParams': {}, 'deviceId': '6fcaacfb-ad1a-4b7a-89f8-ce68bb13960c', 'address': {u'slot': u'0x03', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, 'device': 'bridge', 'type': 'interface', 'name': u'vnet0'}, {'index': '2', 'iface': 'ide', 'name': u'hdc', 'alias': u'ide0-1-0', 'address': {u'bus': u'1', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'0'}, 'specParams': {'path': ''}, 'readonly': 'True', 'deviceId': 'd06fb87c-3646-4586-a83e-86b185880947', 'path': '', 'device': 'cdrom', 'shared': 'false', 'type': 'disk'}, {'index': 0, 'iface': 'virtio', 'type': 'disk', 'name': u'vda', 'format': 'raw', 'bootOrder': u'1', 'specParams': {}, 'readonly': 'False', 'alias': u'virtio-disk0', 'deviceId': '2cdab93d-3bf6-4a50-ba4e-ae3d8934b5e2', 'propagateErrors': 'off', 'address': {u'slot': u'0x06', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, 'device': 'disk', 'shared': 'false', 'path': '/dev/mapper/1cmg02', 'GUID': '1cmg02', 'optional': 'false'}, {'device': u'usb', 'alias': u'usb0', 'type': 'controller', 'address': {u'slot': u'0x01', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x2'}}, {'device': u'ide', 'alias': u'ide0', 'type': 'controller', 'address': {u'slot': u'0x01', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x1'}}, {'device': u'virtio-serial', 'alias': u'virtio-serial0', 'type': 'controller', 'address': {u'slot': u'0x05', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}}, {'device': u'unix', 'alias': u'channel0', 'type': u'channel', 'address': {u'bus': u'0', u'controller': u'0', u'type': u'virtio-serial', u'port': u'1'}}, {'device': u'unix', 'alias': u'channel1', 'type': u'channel', 'address': {u'bus': u'0', u'controller': u'0', u'type': u'virtio-serial', u'port': u'2'}}, {'device': u'spicevmc', 'alias': u'channel2', 'type': u'channel', 'address': {u'bus': u'0', u'controller': u'0', u'type': u'virtio-serial', u'port': u'3'}}, {'index': '1', 'iface': 'virtio', 'name': u'vdb', 'format': 'raw', 'type': 'disk', 'address': {u'slot': u'0x08', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, 'alias': u'virtio-disk1', 'readonly': 'False', 'deviceId': 'fa55b738-1dbe-48dc-a0cc-3d4733e3a344', 'propagateErrors': 'off', 'path': '/dev/mapper/1cmg01', 'device': 'lun', 'shared': 'false', 'GUID': '1cmg01', 'optional': 'false'}], 'smp': '1', 'vmType': 'kvm', 'memSize': 1024, 'displayIp': '0', 'maxVCpus': '160', 'spiceSecureChannels': 'smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard', 'smpCoresPerSocket': '1', 'vmName': 'vm_01', 'display': 'qxl', 'nice': '0'}}
>Thread-153::DEBUG::2014-02-18 14:36:21,776::domainMonitor::192::Storage.DomainMonitorThread::(_monitorDomain) Refreshing domain 227ac6ed-39b0-4e18-a007-7dc7180b4905
>Thread-153::DEBUG::2014-02-18 14:36:21,776::iscsi::393::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
>Thread-153::DEBUG::2014-02-18 14:36:21,776::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
>Thread-153::DEBUG::2014-02-18 14:36:21,788::multipath::110::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath -r' (cwd None)
>Thread-153::DEBUG::2014-02-18 14:36:21,898::multipath::110::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
>Thread-153::DEBUG::2014-02-18 14:36:21,905::fileSD::140::Storage.StorageDomain::(__init__) Reading domain in path /rhev/data-center/mnt/10.34.63.199:_cmg02/227ac6ed-39b0-4e18-a007-7dc7180b4905
>Thread-153::DEBUG::2014-02-18 14:36:21,906::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with FileMetadataRW backend
>Thread-153::DEBUG::2014-02-18 14:36:21,912::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=master', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=Default', 'POOL_DOMAINS=227ac6ed-39b0-4e18-a007-7dc7180b4905:Active', 'POOL_SPM_ID=1', 'POOL_SPM_LVER=0', 'POOL_UUID=00000002-0002-0002-0002-000000000002', 'REMOTE_PATH=10.34.63.199:/cmg02', 'ROLE=Master', 'SDUUID=227ac6ed-39b0-4e18-a007-7dc7180b4905', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=30531a8ccce762fde185e13e5cc13f22e0f8fba9']
>Thread-153::DEBUG::2014-02-18 14:36:21,913::fileSD::575::Storage.StorageDomain::(imageGarbageCollector) Removing remnants of deleted images []
>Thread-153::INFO::2014-02-18 14:36:21,913::sd::374::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace 227ac6ed-39b0-4e18-a007-7dc7180b4905_imageNS already registered
>Thread-153::INFO::2014-02-18 14:36:21,913::sd::382::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace 227ac6ed-39b0-4e18-a007-7dc7180b4905_volumeNS already registered
>Thread-153::DEBUG::2014-02-18 14:36:21,918::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.199:_cmg02/227ac6ed-39b0-4e18-a007-7dc7180b4905/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-153::DEBUG::2014-02-18 14:36:21,923::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n451 bytes (451 B) copied, 0.000291745 s, 1.5 MB/s\n'; <rc> = 0
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:36:22,686::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:36:22,686::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb latency not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:36:22,688::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:36:22,688::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb latency not available
>Thread-1382::DEBUG::2014-02-18 14:36:27,019::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25]
>Thread-1382::INFO::2014-02-18 14:36:27,021::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-1382::INFO::2014-02-18 14:36:27,033::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 2L}}
>Thread-1383::DEBUG::2014-02-18 14:36:27,037::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25]
>Thread-1383::INFO::2014-02-18 14:36:27,038::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-1383::INFO::2014-02-18 14:36:27,041::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '227ac6ed-39b0-4e18-a007-7dc7180b4905:Active', 'master_uuid': '227ac6ed-39b0-4e18-a007-7dc7180b4905', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'227ac6ed-39b0-4e18-a007-7dc7180b4905': {'status': 'Active', 'diskfree': '142286946304', 'isoprefix': '', 'alerts': [], 'disktotal': '144349954048', 'version': 3}}}
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:36:27,694::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:36:27,694::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb latency not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:36:27,695::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:36:27,696::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb latency not available
>Thread-1385::INFO::2014-02-18 14:36:30,656::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-1385::INFO::2014-02-18 14:36:30,656::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'227ac6ed-39b0-4e18-a007-7dc7180b4905': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000291745', 'lastCheck': '8.7', 'valid': True}}
>Thread-1386::DEBUG::2014-02-18 14:36:30,670::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb stats not available
>Thread-1386::DEBUG::2014-02-18 14:36:30,670::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb latency not available
>Thread-153::DEBUG::2014-02-18 14:36:31,936::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.199:_cmg02/227ac6ed-39b0-4e18-a007-7dc7180b4905/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-153::DEBUG::2014-02-18 14:36:31,941::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n451 bytes (451 B) copied, 0.00028792 s, 1.6 MB/s\n'; <rc> = 0
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:36:32,702::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:36:32,705::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb latency not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:36:32,707::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:36:32,707::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb latency not available
>Thread-1390::DEBUG::2014-02-18 14:36:37,062::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25]
>Thread-1390::INFO::2014-02-18 14:36:37,064::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-1390::INFO::2014-02-18 14:36:37,076::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 2L}}
>Thread-1391::DEBUG::2014-02-18 14:36:37,080::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25]
>Thread-1391::INFO::2014-02-18 14:36:37,080::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-1391::INFO::2014-02-18 14:36:37,082::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '227ac6ed-39b0-4e18-a007-7dc7180b4905:Active', 'master_uuid': '227ac6ed-39b0-4e18-a007-7dc7180b4905', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'227ac6ed-39b0-4e18-a007-7dc7180b4905': {'status': 'Active', 'diskfree': '142286946304', 'isoprefix': '', 'alerts': [], 'disktotal': '144349954048', 'version': 3}}}
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:36:37,713::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:36:37,714::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb latency not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:36:37,714::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:36:37,714::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb latency not available
>Thread-153::DEBUG::2014-02-18 14:36:41,948::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.199:_cmg02/227ac6ed-39b0-4e18-a007-7dc7180b4905/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-153::DEBUG::2014-02-18 14:36:41,952::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n451 bytes (451 B) copied, 0.00036316 s, 1.2 MB/s\n'; <rc> = 0
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:36:42,718::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:36:42,718::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb latency not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:36:42,719::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:36:42,719::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb latency not available
>Thread-1394::INFO::2014-02-18 14:36:45,920::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-1394::INFO::2014-02-18 14:36:45,920::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'227ac6ed-39b0-4e18-a007-7dc7180b4905': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00036316', 'lastCheck': '4.0', 'valid': True}}
>Thread-1395::DEBUG::2014-02-18 14:36:45,936::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb stats not available
>Thread-1395::DEBUG::2014-02-18 14:36:45,936::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb latency not available
>Thread-1396::DEBUG::2014-02-18 14:36:47,116::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25]
>Thread-1396::INFO::2014-02-18 14:36:47,116::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-1396::INFO::2014-02-18 14:36:47,128::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 2L}}
>Thread-1397::DEBUG::2014-02-18 14:36:47,132::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25]
>Thread-1397::INFO::2014-02-18 14:36:47,132::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-1397::INFO::2014-02-18 14:36:47,134::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '227ac6ed-39b0-4e18-a007-7dc7180b4905:Active', 'master_uuid': '227ac6ed-39b0-4e18-a007-7dc7180b4905', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'227ac6ed-39b0-4e18-a007-7dc7180b4905': {'status': 'Active', 'diskfree': '142286946304', 'isoprefix': '', 'alerts': [], 'disktotal': '144349954048', 'version': 3}}}
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:36:47,725::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:36:47,725::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb latency not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:36:47,728::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:36:47,728::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb latency not available
>Thread-153::DEBUG::2014-02-18 14:36:51,958::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.199:_cmg02/227ac6ed-39b0-4e18-a007-7dc7180b4905/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-153::DEBUG::2014-02-18 14:36:51,962::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n451 bytes (451 B) copied, 0.000367676 s, 1.2 MB/s\n'; <rc> = 0
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:36:52,734::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:36:52,734::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb latency not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:36:52,736::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:36:52,736::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb latency not available
>Thread-1401::DEBUG::2014-02-18 14:36:57,162::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25]
>Thread-1401::INFO::2014-02-18 14:36:57,163::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-1401::INFO::2014-02-18 14:36:57,174::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 2L}}
>Thread-1402::DEBUG::2014-02-18 14:36:57,178::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25]
>Thread-1402::INFO::2014-02-18 14:36:57,179::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-1402::INFO::2014-02-18 14:36:57,181::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '227ac6ed-39b0-4e18-a007-7dc7180b4905:Active', 'master_uuid': '227ac6ed-39b0-4e18-a007-7dc7180b4905', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'227ac6ed-39b0-4e18-a007-7dc7180b4905': {'status': 'Active', 'diskfree': '142286946304', 'isoprefix': '', 'alerts': [], 'disktotal': '144349954048', 'version': 3}}}
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:36:57,742::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:36:57,742::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb latency not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:36:57,743::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:36:57,744::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb latency not available
>Thread-1404::INFO::2014-02-18 14:37:01,133::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-1404::INFO::2014-02-18 14:37:01,133::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'227ac6ed-39b0-4e18-a007-7dc7180b4905': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000367676', 'lastCheck': '9.2', 'valid': True}}
>Thread-1405::DEBUG::2014-02-18 14:37:01,147::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb stats not available
>Thread-1405::DEBUG::2014-02-18 14:37:01,147::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb latency not available
>Thread-153::DEBUG::2014-02-18 14:37:01,969::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.199:_cmg02/227ac6ed-39b0-4e18-a007-7dc7180b4905/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-153::DEBUG::2014-02-18 14:37:01,973::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n451 bytes (451 B) copied, 0.000501007 s, 900 kB/s\n'; <rc> = 0
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:37:02,750::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:37:02,750::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb latency not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:37:02,751::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:37:02,751::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb latency not available
>Thread-1407::DEBUG::2014-02-18 14:37:07,215::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25]
>Thread-1407::INFO::2014-02-18 14:37:07,215::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-1407::INFO::2014-02-18 14:37:07,227::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 2L}}
>Thread-1408::DEBUG::2014-02-18 14:37:07,232::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25]
>Thread-1408::INFO::2014-02-18 14:37:07,232::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-1408::INFO::2014-02-18 14:37:07,234::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '227ac6ed-39b0-4e18-a007-7dc7180b4905:Active', 'master_uuid': '227ac6ed-39b0-4e18-a007-7dc7180b4905', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'227ac6ed-39b0-4e18-a007-7dc7180b4905': {'status': 'Active', 'diskfree': '142286946304', 'isoprefix': '', 'alerts': [], 'disktotal': '144349954048', 'version': 3}}}
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:37:07,754::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:37:07,754::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb latency not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:37:07,756::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:37:07,756::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb latency not available
>Thread-153::DEBUG::2014-02-18 14:37:11,979::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.199:_cmg02/227ac6ed-39b0-4e18-a007-7dc7180b4905/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-153::DEBUG::2014-02-18 14:37:11,984::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n451 bytes (451 B) copied, 0.00034889 s, 1.3 MB/s\n'; <rc> = 0
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:37:12,762::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:37:12,762::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb latency not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:37:12,763::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:37:12,763::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb latency not available
>Thread-1412::INFO::2014-02-18 14:37:16,298::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-1412::INFO::2014-02-18 14:37:16,298::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'227ac6ed-39b0-4e18-a007-7dc7180b4905': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00034889', 'lastCheck': '4.3', 'valid': True}}
>Thread-1413::DEBUG::2014-02-18 14:37:16,313::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb stats not available
>Thread-1413::DEBUG::2014-02-18 14:37:16,313::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb latency not available
>Thread-1414::DEBUG::2014-02-18 14:37:17,261::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25]
>Thread-1414::INFO::2014-02-18 14:37:17,261::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-1414::INFO::2014-02-18 14:37:17,272::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 2L}}
>Thread-1415::DEBUG::2014-02-18 14:37:17,277::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25]
>Thread-1415::INFO::2014-02-18 14:37:17,277::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-1415::INFO::2014-02-18 14:37:17,279::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '227ac6ed-39b0-4e18-a007-7dc7180b4905:Active', 'master_uuid': '227ac6ed-39b0-4e18-a007-7dc7180b4905', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'227ac6ed-39b0-4e18-a007-7dc7180b4905': {'status': 'Active', 'diskfree': '142286946304', 'isoprefix': '', 'alerts': [], 'disktotal': '144349954048', 'version': 3}}}
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:37:17,769::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:37:17,769::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb latency not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:37:17,771::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:37:17,771::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb latency not available
>Thread-153::DEBUG::2014-02-18 14:37:21,990::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.199:_cmg02/227ac6ed-39b0-4e18-a007-7dc7180b4905/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-153::DEBUG::2014-02-18 14:37:21,994::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n451 bytes (451 B) copied, 0.000329187 s, 1.4 MB/s\n'; <rc> = 0
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:37:22,777::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:37:22,778::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb latency not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:37:22,779::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:37:22,779::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb latency not available
>Thread-1419::DEBUG::2014-02-18 14:37:27,324::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25]
>Thread-1419::INFO::2014-02-18 14:37:27,324::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-1419::INFO::2014-02-18 14:37:27,336::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 2L}}
>Thread-1420::DEBUG::2014-02-18 14:37:27,340::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25]
>Thread-1420::INFO::2014-02-18 14:37:27,341::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-1420::INFO::2014-02-18 14:37:27,343::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '227ac6ed-39b0-4e18-a007-7dc7180b4905:Active', 'master_uuid': '227ac6ed-39b0-4e18-a007-7dc7180b4905', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'227ac6ed-39b0-4e18-a007-7dc7180b4905': {'status': 'Active', 'diskfree': '142286946304', 'isoprefix': '', 'alerts': [], 'disktotal': '144349954048', 'version': 3}}}
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:37:27,785::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:37:27,785::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb latency not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:37:27,786::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:37:27,786::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb latency not available
>Thread-1422::INFO::2014-02-18 14:37:31,504::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-1422::INFO::2014-02-18 14:37:31,505::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'227ac6ed-39b0-4e18-a007-7dc7180b4905': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000329187', 'lastCheck': '9.5', 'valid': True}}
>Thread-1423::DEBUG::2014-02-18 14:37:31,519::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb stats not available
>Thread-1423::DEBUG::2014-02-18 14:37:31,519::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb latency not available
>Thread-153::DEBUG::2014-02-18 14:37:32,001::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.199:_cmg02/227ac6ed-39b0-4e18-a007-7dc7180b4905/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-153::DEBUG::2014-02-18 14:37:32,006::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n451 bytes (451 B) copied, 0.000363903 s, 1.2 MB/s\n'; <rc> = 0
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:37:32,792::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:37:32,792::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb latency not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:37:32,793::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:37:32,794::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb latency not available
>Thread-1425::DEBUG::2014-02-18 14:37:37,368::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25]
>Thread-1425::INFO::2014-02-18 14:37:37,368::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-1425::INFO::2014-02-18 14:37:37,380::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 2L}}
>Thread-1426::DEBUG::2014-02-18 14:37:37,384::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25]
>Thread-1426::INFO::2014-02-18 14:37:37,384::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-1426::INFO::2014-02-18 14:37:37,386::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '227ac6ed-39b0-4e18-a007-7dc7180b4905:Active', 'master_uuid': '227ac6ed-39b0-4e18-a007-7dc7180b4905', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'227ac6ed-39b0-4e18-a007-7dc7180b4905': {'status': 'Active', 'diskfree': '142286946304', 'isoprefix': '', 'alerts': [], 'disktotal': '144349954048', 'version': 3}}}
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:37:37,799::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:37:37,800::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb latency not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:37:37,801::vm::641::vm.Vm::(_getDiskStats) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb stats not available
>GuestMonitor-vm_01::DEBUG::2014-02-18 14:37:37,801::vm::680::vm.Vm::(_getDiskLatency) vmId=`1bef6ac1-6dc1-4fae-ae30-4cdc39cac74f`::Disk vdb latency not available
>Thread-153::DEBUG::2014-02-18 14:37:42,012::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.199:_cmg02/227ac6ed-39b0-4e18-a007-7dc7180b4905/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-153::DEBUG::2014-02-18 14:37:42,016::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n451 bytes (451 B) copied, 0.000419592 s, 1.1 MB/s\n'; <rc> = 0
>Thread-1430::INFO::2014-02-18 14:37:46,699::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-1430::INFO::2014-02-18 14:37:46,699::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'227ac6ed-39b0-4e18-a007-7dc7180b4905': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000419592', 'lastCheck': '4.7', 'valid': True}}
>Thread-1432::DEBUG::2014-02-18 14:37:47,423::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25]
>Thread-1432::INFO::2014-02-18 14:37:47,423::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-1432::INFO::2014-02-18 14:37:47,435::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 2L}}
>Thread-1433::DEBUG::2014-02-18 14:37:47,439::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25]
>Thread-1433::INFO::2014-02-18 14:37:47,439::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-1433::INFO::2014-02-18 14:37:47,441::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '227ac6ed-39b0-4e18-a007-7dc7180b4905:Active', 'master_uuid': '227ac6ed-39b0-4e18-a007-7dc7180b4905', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'227ac6ed-39b0-4e18-a007-7dc7180b4905': {'status': 'Active', 'diskfree': '142286946304', 'isoprefix': '', 'alerts': [], 'disktotal': '144349954048', 'version': 3}}}
>Thread-153::DEBUG::2014-02-18 14:37:52,023::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.199:_cmg02/227ac6ed-39b0-4e18-a007-7dc7180b4905/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-153::DEBUG::2014-02-18 14:37:52,027::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n451 bytes (451 B) copied, 0.000400834 s, 1.1 MB/s\n'; <rc> = 0
>Thread-1437::DEBUG::2014-02-18 14:37:57,469::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25]
>Thread-1437::INFO::2014-02-18 14:37:57,470::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-1437::INFO::2014-02-18 14:37:57,481::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 2L}}
>Thread-1438::DEBUG::2014-02-18 14:37:57,486::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25]
>Thread-1438::INFO::2014-02-18 14:37:57,486::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-1438::INFO::2014-02-18 14:37:57,488::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '227ac6ed-39b0-4e18-a007-7dc7180b4905:Active', 'master_uuid': '227ac6ed-39b0-4e18-a007-7dc7180b4905', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'227ac6ed-39b0-4e18-a007-7dc7180b4905': {'status': 'Active', 'diskfree': '142286946304', 'isoprefix': '', 'alerts': [], 'disktotal': '144349954048', 'version': 3}}}
>Thread-1440::INFO::2014-02-18 14:38:01,909::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-1440::INFO::2014-02-18 14:38:01,909::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'227ac6ed-39b0-4e18-a007-7dc7180b4905': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000400834', 'lastCheck': '9.9', 'valid': True}}
>Thread-153::DEBUG::2014-02-18 14:38:02,033::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.199:_cmg02/227ac6ed-39b0-4e18-a007-7dc7180b4905/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-153::DEBUG::2014-02-18 14:38:02,038::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n451 bytes (451 B) copied, 0.000312696 s, 1.4 MB/s\n'; <rc> = 0
>Thread-1443::DEBUG::2014-02-18 14:38:07,543::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25]
>Thread-1443::INFO::2014-02-18 14:38:07,543::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-1443::INFO::2014-02-18 14:38:07,555::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 2L}}
>Thread-1444::DEBUG::2014-02-18 14:38:07,559::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25]
>Thread-1444::INFO::2014-02-18 14:38:07,560::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-1444::INFO::2014-02-18 14:38:07,562::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '227ac6ed-39b0-4e18-a007-7dc7180b4905:Active', 'master_uuid': '227ac6ed-39b0-4e18-a007-7dc7180b4905', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'227ac6ed-39b0-4e18-a007-7dc7180b4905': {'status': 'Active', 'diskfree': '142286946304', 'isoprefix': '', 'alerts': [], 'disktotal': '144349954048', 'version': 3}}}
>Thread-153::DEBUG::2014-02-18 14:38:12,044::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.199:_cmg02/227ac6ed-39b0-4e18-a007-7dc7180b4905/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-153::DEBUG::2014-02-18 14:38:12,048::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n451 bytes (451 B) copied, 0.000308038 s, 1.5 MB/s\n'; <rc> = 0
>Thread-1448::INFO::2014-02-18 14:38:17,063::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-1448::INFO::2014-02-18 14:38:17,063::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'227ac6ed-39b0-4e18-a007-7dc7180b4905': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000308038', 'lastCheck': '5.0', 'valid': True}}
>Thread-1450::DEBUG::2014-02-18 14:38:17,590::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25]
>Thread-1450::INFO::2014-02-18 14:38:17,590::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-1450::INFO::2014-02-18 14:38:17,601::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 2L}}
>Thread-1451::DEBUG::2014-02-18 14:38:17,606::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25]
>Thread-1451::INFO::2014-02-18 14:38:17,606::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-1451::INFO::2014-02-18 14:38:17,608::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '227ac6ed-39b0-4e18-a007-7dc7180b4905:Active', 'master_uuid': '227ac6ed-39b0-4e18-a007-7dc7180b4905', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'227ac6ed-39b0-4e18-a007-7dc7180b4905': {'status': 'Active', 'diskfree': '142286946304', 'isoprefix': '', 'alerts': [], 'disktotal': '144349954048', 'version': 3}}}
>Thread-153::DEBUG::2014-02-18 14:38:22,054::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.199:_cmg02/227ac6ed-39b0-4e18-a007-7dc7180b4905/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-153::DEBUG::2014-02-18 14:38:22,058::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n451 bytes (451 B) copied, 0.000442211 s, 1.0 MB/s\n'; <rc> = 0
>Thread-1455::DEBUG::2014-02-18 14:38:27,647::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25]
>Thread-1455::INFO::2014-02-18 14:38:27,647::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-1455::INFO::2014-02-18 14:38:27,659::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 2L}}
>Thread-1456::DEBUG::2014-02-18 14:38:27,663::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25]
>Thread-1456::INFO::2014-02-18 14:38:27,664::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-1456::INFO::2014-02-18 14:38:27,666::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '227ac6ed-39b0-4e18-a007-7dc7180b4905:Active', 'master_uuid': '227ac6ed-39b0-4e18-a007-7dc7180b4905', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'227ac6ed-39b0-4e18-a007-7dc7180b4905': {'status': 'Active', 'diskfree': '142286946304', 'isoprefix': '', 'alerts': [], 'disktotal': '144349954048', 'version': 3}}}
>Thread-153::DEBUG::2014-02-18 14:38:32,066::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.199:_cmg02/227ac6ed-39b0-4e18-a007-7dc7180b4905/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-153::DEBUG::2014-02-18 14:38:32,070::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n451 bytes (451 B) copied, 0.000327069 s, 1.4 MB/s\n'; <rc> = 0
>Thread-1458::INFO::2014-02-18 14:38:32,284::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-1458::INFO::2014-02-18 14:38:32,284::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'227ac6ed-39b0-4e18-a007-7dc7180b4905': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000327069', 'lastCheck': '0.2', 'valid': True}}
>Thread-1461::DEBUG::2014-02-18 14:38:37,705::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25]
>Thread-1461::INFO::2014-02-18 14:38:37,706::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-1461::INFO::2014-02-18 14:38:37,717::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 2L}}
>Thread-1462::DEBUG::2014-02-18 14:38:37,722::BindingXMLRPC::159::vds::(wrapper) client [10.34.63.25]
>Thread-1462::INFO::2014-02-18 14:38:37,722::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-1462::INFO::2014-02-18 14:38:37,724::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '227ac6ed-39b0-4e18-a007-7dc7180b4905:Active', 'master_uuid': '227ac6ed-39b0-4e18-a007-7dc7180b4905', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'227ac6ed-39b0-4e18-a007-7dc7180b4905': {'status': 'Active', 'diskfree': '142286946304', 'isoprefix': '', 'alerts': [], 'disktotal': '144349954048', 'version': 3}}}

Actions: View

Attachments on bug 1044068: 864563