Login
[x]
Log in using an account from:
Fedora Account System
Red Hat Associate
Red Hat Customer
Or login using a Red Hat Bugzilla account
Forgot Password
Login:
Hide Forgot
Create an Account
Red Hat Bugzilla – Attachment 864563 Details for
Bug 1044068
vmHotplugDisk failed with "VolumeError: Bad volume specification"
[?]
New
Simple Search
Advanced Search
My Links
Browse
Requests
Reports
Current State
Search
Tabular reports
Graphical reports
Duplicates
Other Reports
User Changes
Plotly Reports
Bug Status
Bug Severity
Non-Defaults
|
Product Dashboard
Help
Page Help!
Bug Writing Guidelines
What's new
Browser Support Policy
5.0.4.rh83 Release notes
FAQ
Guides index
User guide
Web Services
Contact
Legal
This site requires JavaScript to be enabled to function correctly, please enable it.
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:
verifying vdsm log.
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}}}
You cannot view the attachment while viewing its details because your browser does not support IFRAMEs.
View the attachment on a separate page
.
View Attachment As Raw
Actions:
View
Attachments on
bug 1044068
: 864563