jsonrpc.Executor/1::DEBUG::2016-06-27 11:19:57,344::__init__::503::jsonrpc.JsonRpcServer::(_serveRequest) Calling 'VM.create' in bridge with {u'vmParams': {u'acpiEnable': u'true', u'emulatedMachine': u'pc-i440fx-rhel7.2.0', u'vmId': u'25267411-1ec2-4220-82dc-4ae048255fb0', u'memGuaranteedSize': 682, u'transparentHugePages': u'true', u'timeOffset': u'0', u'cpuType': u'Haswell-noTSX', u'custom': {u'device_8c35d886-872f-4dc1-9464-2efee62137a4device_5586a2bf-f164-4fe2-8335-088a9109f44e': u"VmDevice:{id='VmDeviceId:{deviceId='5586a2bf-f164-4fe2-8335-088a9109f44e', vmId='25267411-1ec2-4220-82dc-4ae048255fb0'}', device='unix', type='CHANNEL', bootOrder='0', specParams='[]', address='{bus=0, controller=0, type=virtio-serial, port=1}', managed='false', plugged='true', readOnly='false', deviceAlias='channel0', customProperties='[]', snapshotId='null', logicalName='null', usingScsiReservation='false'}", u'device_8c35d886-872f-4dc1-9464-2efee62137a4device_5586a2bf-f164-4fe2-8335-088a9109f44edevice_e637898d-11e8-4bf5-b301-c33d78167c1ddevice_d7d04f26-05f3-4e9c-8d97-6af15a80591f': u"VmDevice:{id='VmDeviceId:{deviceId='d7d04f26-05f3-4e9c-8d97-6af15a80591f', vmId='25267411-1ec2-4220-82dc-4ae048255fb0'}', device='spicevmc', type='CHANNEL', bootOrder='0', specParams='[]', address='{bus=0, controller=0, type=virtio-serial, port=3}', managed='false', plugged='true', readOnly='false', deviceAlias='channel2', customProperties='[]', snapshotId='null', logicalName='null', usingScsiReservation='false'}", u'device_8c35d886-872f-4dc1-9464-2efee62137a4': u"VmDevice:{id='VmDeviceId:{deviceId='8c35d886-872f-4dc1-9464-2efee62137a4', vmId='25267411-1ec2-4220-82dc-4ae048255fb0'}', device='ide', type='CONTROLLER', bootOrder='0', specParams='[]', address='{slot=0x01, bus=0x00, domain=0x0000, type=pci, function=0x1}', managed='false', plugged='true', readOnly='false', deviceAlias='ide', customProperties='[]', snapshotId='null', logicalName='null', usingScsiReservation='false'}", u'device_8c35d886-872f-4dc1-9464-2efee62137a4device_5586a2bf-f164-4fe2-8335-088a9109f44edevice_e637898d-11e8-4bf5-b301-c33d78167c1d': u"VmDevice:{id='VmDeviceId:{deviceId='e637898d-11e8-4bf5-b301-c33d78167c1d', vmId='25267411-1ec2-4220-82dc-4ae048255fb0'}', device='unix', type='CHANNEL', bootOrder='0', specParams='[]', address='{bus=0, controller=0, type=virtio-serial, port=2}', managed='false', plugged='true', readOnly='false', deviceAlias='channel1', customProperties='[]', snapshotId='null', logicalName='null', usingScsiReservation='false'}"}, u'guestNumaNodes': [{u'nodeIndex': 0, u'cpus': u'0,1,2,3', u'memory': u'1024'}], u'numaTune': {u'nodeset': u'1,0', u'mode': u'interleave'}, u'smp': u'4', u'vmType': u'kvm', u'spiceSslCipherSuite': u'DEFAULT', u'memSize': 1024, u'smpCoresPerSocket': u'2', u'vmName': u'TestVM_Amestris', u'nice': u'0', u'maxMemSize': 4194304, u'bootMenuEnable': u'false', u'copyPasteEnable': u'true', u'smpThreadsPerCore': u'1', u'smartcardEnable': u'false', u'maxMemSlots': 16, u'fileTransferEnable': u'true', u'keyboardLayout': u'en-us', u'kvmEnable': u'true', u'pitReinjection': u'false', u'displayNetwork': u'ovirtmgmt', u'devices': [{u'device': u'qxl', u'specParams': {u'vram': u'32768', u'ram': u'65536', u'heads': u'1'}, u'type': u'video', u'deviceId': u'0ffeff5c-19bb-44c0-8107-447779a672c8', u'address': {u'function': u'0x0', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'slot': u'0x02'}}, {u'device': u'spice', u'specParams': {u'fileTransferEnable': u'true', u'copyPasteEnable': u'true'}, u'type': u'graphics', u'deviceId': u'2b5a92d5-6d46-4a7f-b781-e277260fa1c5'}, {u'index': u'2', u'iface': u'ide', u'specParams': {u'path': u''}, u'readonly': u'true', u'deviceId': u'8e35d253-df2f-4920-b8d8-2a29735d148c', u'address': {u'bus': u'1', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'0'}, u'device': u'cdrom', u'shared': u'false', u'path': u'', u'type': u'disk'}, {u'index': 0, u'domainID': u'2fec15c6-8f63-4a8b-ad94-00ddb9db625e', u'bootOrder': u'1', u'format': u'raw', u'type': u'disk', u'poolID': u'91958960-de08-4eb5-b8ab-92ba066dfda0', u'volumeID': u'3c492e23-5cf9-4d13-89c5-74268076f234', u'imageID': u'22648231-5420-4f7f-a81b-d57f7b98da77', u'specParams': {}, u'readonly': u'false', u'iface': u'virtio', u'deviceId': u'22648231-5420-4f7f-a81b-d57f7b98da77', u'address': {u'function': u'0x0', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'slot': u'0x05'}, u'device': u'disk', u'shared': u'false', u'propagateErrors': u'off', u'optional': u'false'}, {u'nicModel': u'pv', u'macAddr': u'00:1a:4a:16:01:55', u'linkActive': u'true', u'network': u'ovirtmgmt', u'filter': u'vdsm-no-mac-spoofing', u'specParams': {u'inbound': {}, u'outbound': {}}, u'deviceId': u'5ecd077b-15bf-44b6-855e-039ebec8f0bf', u'address': {u'function': u'0x0', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'slot': u'0x07'}, u'device': u'bridge', u'type': u'interface'}, {u'device': u'memballoon', u'specParams': {u'model': u'virtio'}, u'type': u'balloon', u'deviceId': u'dcf132ee-5b8e-4d4b-a160-19aeea5b7e50', u'address': {u'function': u'0x0', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'slot': u'0x06'}}, {u'device': u'virtio-serial', u'specParams': {}, u'type': u'controller', u'deviceId': u'7787219c-b86d-4e80-ad23-bb95c97730d5', u'address': {u'function': u'0x0', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'slot': u'0x04'}}], u'maxVCpus': u'32', u'spiceSecureChannels': u'smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard', u'display': u'qxl'}, u'vmID': u'25267411-1ec2-4220-82dc-4ae048255fb0'}
jsonrpc.Executor/1::DEBUG::2016-06-27 11:19:57,348::__init__::533::jsonrpc.JsonRpcServer::(_serveRequest) Return 'VM.create' in bridge with {u'acpiEnable': u'true', u'emulatedMachine': u'pc-i440fx-rhel7.2.0', 'pid': '0', u'memGuaranteedSize': 682, u'transparentHugePages': u'true', 'displayPort': '-1', 'displaySecurePort': '-1', u'spiceSslCipherSuite': u'DEFAULT', u'cpuType': u'Haswell-noTSX', u'smp': u'4', u'guestNumaNodes': [{u'nodeIndex': 0, u'cpus': u'0,1,2,3', u'memory': u'1024'}], u'smartcardEnable': u'false', u'numaTune': {u'nodeset': u'1,0', u'mode': u'interleave'}, u'custom': {u'device_8c35d886-872f-4dc1-9464-2efee62137a4device_5586a2bf-f164-4fe2-8335-088a9109f44e': u"VmDevice:{id='VmDeviceId:{deviceId='5586a2bf-f164-4fe2-8335-088a9109f44e', vmId='25267411-1ec2-4220-82dc-4ae048255fb0'}', device='unix', type='CHANNEL', bootOrder='0', specParams='[]', address='{bus=0, controller=0, type=virtio-serial, port=1}', managed='false', plugged='true', readOnly='false', deviceAlias='channel0', customProperties='[]', snapshotId='null', logicalName='null', usingScsiReservation='false'}", u'device_8c35d886-872f-4dc1-9464-2efee62137a4device_5586a2bf-f164-4fe2-8335-088a9109f44edevice_e637898d-11e8-4bf5-b301-c33d78167c1ddevice_d7d04f26-05f3-4e9c-8d97-6af15a80591f': u"VmDevice:{id='VmDeviceId:{deviceId='d7d04f26-05f3-4e9c-8d97-6af15a80591f', vmId='25267411-1ec2-4220-82dc-4ae048255fb0'}', device='spicevmc', type='CHANNEL', bootOrder='0', specParams='[]', address='{bus=0, controller=0, type=virtio-serial, port=3}', managed='false', plugged='true', readOnly='false', deviceAlias='channel2', customProperties='[]', snapshotId='null', logicalName='null', usingScsiReservation='false'}", u'device_8c35d886-872f-4dc1-9464-2efee62137a4': u"VmDevice:{id='VmDeviceId:{deviceId='8c35d886-872f-4dc1-9464-2efee62137a4', vmId='25267411-1ec2-4220-82dc-4ae048255fb0'}', device='ide', type='CONTROLLER', bootOrder='0', specParams='[]', address='{slot=0x01, bus=0x00, domain=0x0000, type=pci, function=0x1}', managed='false', plugged='true', readOnly='false', deviceAlias='ide', customProperties='[]', snapshotId='null', logicalName='null', usingScsiReservation='false'}", u'device_8c35d886-872f-4dc1-9464-2efee62137a4device_5586a2bf-f164-4fe2-8335-088a9109f44edevice_e637898d-11e8-4bf5-b301-c33d78167c1d': u"VmDevice:{id='VmDeviceId:{deviceId='e637898d-11e8-4bf5-b301-c33d78167c1d', vmId='25267411-1ec2-4220-82dc-4ae048255fb0'}', device='unix', type='CHANNEL', bootOrder='0', specParams='[]', address='{bus=0, controller=0, type=virtio-serial, port=2}', managed='false', plugged='true', readOnly='false', deviceAlias='channel1', customProperties='[]', snapshotId='null', logicalName='null', usingScsiReservation='false'}"}, u'vmType': u'kvm', u'memSize': 1024, u'smpCoresPerSocket': u'2', u'vmName': u'TestVM_Amestris', u'nice': u'0', 'status': 'WaitForLaunch', u'maxMemSize': 4194304, u'bootMenuEnable': u'false', u'vmId': u'25267411-1ec2-4220-82dc-4ae048255fb0', u'copyPasteEnable': u'true', 'displayIp': '10.40.150.221', u'smpThreadsPerCore': u'1', 'guestDiskMapping': {}, u'spiceSecureChannels': u'smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard', u'fileTransferEnable': u'true', 'nicModel': 'rtl8139,pv', u'keyboardLayout': u'en-us', u'kvmEnable': u'true', u'pitReinjection': u'false', u'displayNetwork': u'ovirtmgmt', u'devices': [{u'specParams': {u'vram': u'32768', u'ram': u'65536', u'heads': u'1'}, 'deviceType': u'video', u'deviceId': u'0ffeff5c-19bb-44c0-8107-447779a672c8', u'address': {u'function': u'0x0', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'slot': u'0x02'}, u'device': u'qxl', u'type': u'video'}, {u'device': u'spice', u'specParams': {u'fileTransferEnable': u'true', u'copyPasteEnable': u'true'}, 'deviceType': u'graphics', u'type': u'graphics', u'deviceId': u'2b5a92d5-6d46-4a7f-b781-e277260fa1c5'}, {u'index': u'2', u'iface': u'ide', u'specParams': {u'path': u''}, u'readonly': u'true', 'deviceType': u'disk', u'deviceId': u'8e35d253-df2f-4920-b8d8-2a29735d148c', u'address': {u'bus': u'1', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'0'}, u'device': u'cdrom', u'shared': u'false', u'path': u'', u'type': u'disk'}, {u'index': 0, u'domainID': u'2fec15c6-8f63-4a8b-ad94-00ddb9db625e', u'format': u'raw', 'deviceType': u'disk', u'bootOrder': u'1', u'address': {u'function': u'0x0', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'slot': u'0x05'}, u'volumeID': u'3c492e23-5cf9-4d13-89c5-74268076f234', u'imageID': u'22648231-5420-4f7f-a81b-d57f7b98da77', u'specParams': {}, u'readonly': u'false', u'iface': u'virtio', u'optional': u'false', u'deviceId': u'22648231-5420-4f7f-a81b-d57f7b98da77', u'poolID': u'91958960-de08-4eb5-b8ab-92ba066dfda0', u'device': u'disk', u'shared': u'false', u'propagateErrors': u'off', u'type': u'disk'}, {u'nicModel': u'pv', u'macAddr': u'00:1a:4a:16:01:55', u'linkActive': u'true', u'network': u'ovirtmgmt', u'filter': u'vdsm-no-mac-spoofing', u'specParams': {u'inbound': {}, u'outbound': {}}, 'deviceType': u'interface', u'deviceId': u'5ecd077b-15bf-44b6-855e-039ebec8f0bf', u'address': {u'function': u'0x0', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'slot': u'0x07'}, u'device': u'bridge', u'type': u'interface'}, {u'specParams': {u'model': u'virtio'}, 'deviceType': u'balloon', u'deviceId': u'dcf132ee-5b8e-4d4b-a160-19aeea5b7e50', u'address': {u'function': u'0x0', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'slot': u'0x06'}, u'device': u'memballoon', u'type': u'balloon'}, {u'specParams': {}, 'deviceType': u'controller', u'deviceId': u'7787219c-b86d-4e80-ad23-bb95c97730d5', u'address': {u'function': u'0x0', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'slot': u'0x04'}, u'device': u'virtio-serial', u'type': u'controller'}], u'display': 'qxl', u'timeOffset': u'0', u'maxVCpus': u'32', 'clientIp': '', 'statusTime': '13350439370', u'maxMemSlots': 16}
Thread-18100::DEBUG::2016-06-27 11:19:57,350::vm::697::virt.vm::(_startUnderlyingVm) vmId=`25267411-1ec2-4220-82dc-4ae048255fb0`::Start
Thread-18100::INFO::2016-06-27 11:19:57,350::vm::1850::virt.vm::(_run) vmId=`25267411-1ec2-4220-82dc-4ae048255fb0`::VM wrapper has started
Thread-18100::DEBUG::2016-06-27 11:19:57,350::task::595::Storage.TaskManager.Task::(_updateState) Task=`c716ff04-9f80-43d2-9e42-a8279952f2e8`::moving from state init -> state preparing
Thread-18100::INFO::2016-06-27 11:19:57,351::logUtils::48::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID=u'2fec15c6-8f63-4a8b-ad94-00ddb9db625e', spUUID=u'91958960-de08-4eb5-b8ab-92ba066dfda0', imgUUID=u'22648231-5420-4f7f-a81b-d57f7b98da77', volUUID=u'3c492e23-5cf9-4d13-89c5-74268076f234', options=None)
Thread-18100::DEBUG::2016-06-27 11:19:57,351::lvm::427::Storage.OperationMutex::(_reloadlvs) Operation 'lvm reload operation' got the operation mutex
Thread-18100::DEBUG::2016-06-27 11:19:57,351::lvm::290::Storage.Misc.excCmd::(cmd) /usr/bin/taskset --cpu-list 0-31 /usr/bin/sudo -n /usr/sbin/lvm lvs --config ' devices { preferred_names = ["^/dev/mapper/"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 filter = [ '\''a|/dev/mapper/360000000000000000e0000000001000a|'\'', '\''r|.*|'\'' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } ' --noheadings --units b --nosuffix --separator '|' --ignoreskippedcluster -o uuid,name,vg_name,attr,size,seg_start_pe,devices,tags 2fec15c6-8f63-4a8b-ad94-00ddb9db625e (cwd None)
Thread-18100::DEBUG::2016-06-27 11:19:57,670::lvm::290::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  WARNING: lvmetad is running but disabled. Restart lvmetad before enabling it!\n'; <rc> = 0
Thread-18100::DEBUG::2016-06-27 11:19:57,671::lvm::462::Storage.LVM::(_reloadlvs) lvs reloaded
Thread-18100::DEBUG::2016-06-27 11:19:57,671::lvm::462::Storage.OperationMutex::(_reloadlvs) Operation 'lvm reload operation' released the operation mutex
Thread-18100::INFO::2016-06-27 11:19:57,671::logUtils::51::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '26843545600', 'apparentsize': '26843545600'}
Thread-18100::DEBUG::2016-06-27 11:19:57,672::task::1191::Storage.TaskManager.Task::(prepare) Task=`c716ff04-9f80-43d2-9e42-a8279952f2e8`::finished: {'truesize': '26843545600', 'apparentsize': '26843545600'}
Thread-18100::DEBUG::2016-06-27 11:19:57,672::task::595::Storage.TaskManager.Task::(_updateState) Task=`c716ff04-9f80-43d2-9e42-a8279952f2e8`::moving from state preparing -> state finished
Thread-18100::DEBUG::2016-06-27 11:19:57,672::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-18100::DEBUG::2016-06-27 11:19:57,672::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-18100::DEBUG::2016-06-27 11:19:57,672::task::993::Storage.TaskManager.Task::(_decref) Task=`c716ff04-9f80-43d2-9e42-a8279952f2e8`::ref 0 aborting False
Thread-18100::INFO::2016-06-27 11:19:57,672::clientIF::375::vds::(prepareVolumePath) prepared volume path: 
Thread-18100::DEBUG::2016-06-27 11:19:57,673::task::595::Storage.TaskManager.Task::(_updateState) Task=`9009aa95-304b-4757-8e0c-55f73bff16f3`::moving from state init -> state preparing
Thread-18100::INFO::2016-06-27 11:19:57,673::logUtils::48::dispatcher::(wrapper) Run and protect: prepareImage(sdUUID=u'2fec15c6-8f63-4a8b-ad94-00ddb9db625e', spUUID=u'91958960-de08-4eb5-b8ab-92ba066dfda0', imgUUID=u'22648231-5420-4f7f-a81b-d57f7b98da77', leafUUID=u'3c492e23-5cf9-4d13-89c5-74268076f234')
Thread-18100::DEBUG::2016-06-27 11:19:57,673::resourceManager::199::Storage.ResourceManager.Request::(__init__) ResName=`Storage.2fec15c6-8f63-4a8b-ad94-00ddb9db625e`ReqID=`85f26399-5fe4-4762-84fc-d3e051da8502`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3213' at 'prepareImage'
Thread-18100::DEBUG::2016-06-27 11:19:57,673::resourceManager::545::Storage.ResourceManager::(registerResource) Trying to register resource 'Storage.2fec15c6-8f63-4a8b-ad94-00ddb9db625e' for lock type 'shared'
Thread-18100::DEBUG::2016-06-27 11:19:57,673::resourceManager::604::Storage.ResourceManager::(registerResource) Resource 'Storage.2fec15c6-8f63-4a8b-ad94-00ddb9db625e' is free. Now locking as 'shared' (1 active user)
Thread-18100::DEBUG::2016-06-27 11:19:57,674::resourceManager::239::Storage.ResourceManager.Request::(grant) ResName=`Storage.2fec15c6-8f63-4a8b-ad94-00ddb9db625e`ReqID=`85f26399-5fe4-4762-84fc-d3e051da8502`::Granted request
Thread-18100::DEBUG::2016-06-27 11:19:57,674::task::827::Storage.TaskManager.Task::(resourceAcquired) Task=`9009aa95-304b-4757-8e0c-55f73bff16f3`::_resourcesAcquired: Storage.2fec15c6-8f63-4a8b-ad94-00ddb9db625e (shared)
Thread-18100::DEBUG::2016-06-27 11:19:57,674::task::993::Storage.TaskManager.Task::(_decref) Task=`9009aa95-304b-4757-8e0c-55f73bff16f3`::ref 1 aborting False
Thread-18100::DEBUG::2016-06-27 11:19:57,674::lvm::427::Storage.OperationMutex::(_reloadlvs) Operation 'lvm reload operation' got the operation mutex
Thread-18100::DEBUG::2016-06-27 11:19:57,674::lvm::290::Storage.Misc.excCmd::(cmd) /usr/bin/taskset --cpu-list 0-31 /usr/bin/sudo -n /usr/sbin/lvm lvs --config ' devices { preferred_names = ["^/dev/mapper/"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 filter = [ '\''a|/dev/mapper/360000000000000000e0000000001000a|'\'', '\''r|.*|'\'' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } ' --noheadings --units b --nosuffix --separator '|' --ignoreskippedcluster -o uuid,name,vg_name,attr,size,seg_start_pe,devices,tags 2fec15c6-8f63-4a8b-ad94-00ddb9db625e (cwd None)
Thread-18100::DEBUG::2016-06-27 11:19:57,834::lvm::290::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  WARNING: lvmetad is running but disabled. Restart lvmetad before enabling it!\n'; <rc> = 0
Thread-18100::DEBUG::2016-06-27 11:19:57,834::lvm::462::Storage.LVM::(_reloadlvs) lvs reloaded
Thread-18100::DEBUG::2016-06-27 11:19:57,835::lvm::462::Storage.OperationMutex::(_reloadlvs) Operation 'lvm reload operation' released the operation mutex
Thread-18100::DEBUG::2016-06-27 11:19:57,836::blockVolume::631::Storage.Misc.excCmd::(getMetadata) /usr/bin/taskset --cpu-list 0-31 /usr/bin/dd iflag=direct skip=11 bs=512 if=/dev/2fec15c6-8f63-4a8b-ad94-00ddb9db625e/metadata count=1 (cwd None)
Thread-18100::DEBUG::2016-06-27 11:19:57,846::blockVolume::631::Storage.Misc.excCmd::(getMetadata) SUCCESS: <err> = '1+0 records in\n1+0 records out\n512 bytes (512 B) copied, 0.000680404 s, 752 kB/s\n'; <rc> = 0
Thread-18100::DEBUG::2016-06-27 11:19:57,847::misc::261::Storage.Misc::(validateDDBytes) err: ['1+0 records in', '1+0 records out', '512 bytes (512 B) copied, 0.000680404 s, 752 kB/s'], size: 512
Thread-18100::DEBUG::2016-06-27 11:19:57,847::lvm::290::Storage.Misc.excCmd::(cmd) /usr/bin/taskset --cpu-list 0-31 /usr/bin/sudo -n /usr/sbin/lvm lvchange --config ' devices { preferred_names = ["^/dev/mapper/"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 filter = [ '\''a|/dev/mapper/360000000000000000e0000000001000a|'\'', '\''r|.*|'\'' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } ' --autobackup n --available y 2fec15c6-8f63-4a8b-ad94-00ddb9db625e/3c492e23-5cf9-4d13-89c5-74268076f234 (cwd None)
mailbox.SPMMonitor::DEBUG::2016-06-27 11:19:57,904::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) /usr/bin/taskset --cpu-list 0-31 dd if=/rhev/data-center/91958960-de08-4eb5-b8ab-92ba066dfda0/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000 (cwd None)
mailbox.SPMMonitor::DEBUG::2016-06-27 11:19:57,928::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0122238 s, 83.8 MB/s\n'; <rc> = 0
Thread-18100::DEBUG::2016-06-27 11:19:58,013::lvm::290::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  WARNING: lvmetad is running but disabled. Restart lvmetad before enabling it!\n'; <rc> = 0
Thread-18100::DEBUG::2016-06-27 11:19:58,014::lvm::513::Storage.OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-18100::DEBUG::2016-06-27 11:19:58,014::lvm::525::Storage.OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-18100::DEBUG::2016-06-27 11:19:58,014::fileUtils::143::Storage.fileUtils::(createdir) Creating directory: /var/run/vdsm/storage/2fec15c6-8f63-4a8b-ad94-00ddb9db625e/22648231-5420-4f7f-a81b-d57f7b98da77 mode: None
Thread-18100::DEBUG::2016-06-27 11:19:58,014::blockSD::1108::Storage.StorageDomain::(createImageLinks) Creating symlink from /dev/2fec15c6-8f63-4a8b-ad94-00ddb9db625e/3c492e23-5cf9-4d13-89c5-74268076f234 to /var/run/vdsm/storage/2fec15c6-8f63-4a8b-ad94-00ddb9db625e/22648231-5420-4f7f-a81b-d57f7b98da77/3c492e23-5cf9-4d13-89c5-74268076f234
Thread-18100::DEBUG::2016-06-27 11:19:58,014::blockSD::1072::Storage.StorageDomain::(linkBCImage) Creating symlink from /var/run/vdsm/storage/2fec15c6-8f63-4a8b-ad94-00ddb9db625e/22648231-5420-4f7f-a81b-d57f7b98da77 to /rhev/data-center/91958960-de08-4eb5-b8ab-92ba066dfda0/2fec15c6-8f63-4a8b-ad94-00ddb9db625e/images/22648231-5420-4f7f-a81b-d57f7b98da77
Thread-18100::DEBUG::2016-06-27 11:19:58,015::blockSD::1078::Storage.StorageDomain::(linkBCImage) path to image directory already exists: /rhev/data-center/91958960-de08-4eb5-b8ab-92ba066dfda0/2fec15c6-8f63-4a8b-ad94-00ddb9db625e/images/22648231-5420-4f7f-a81b-d57f7b98da77
Thread-18100::DEBUG::2016-06-27 11:19:58,015::lvm::427::Storage.OperationMutex::(_reloadlvs) Operation 'lvm reload operation' got the operation mutex
Thread-18100::DEBUG::2016-06-27 11:19:58,015::lvm::290::Storage.Misc.excCmd::(cmd) /usr/bin/taskset --cpu-list 0-31 /usr/bin/sudo -n /usr/sbin/lvm lvs --config ' devices { preferred_names = ["^/dev/mapper/"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 filter = [ '\''a|/dev/mapper/360000000000000000e0000000001000a|'\'', '\''r|.*|'\'' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } ' --noheadings --units b --nosuffix --separator '|' --ignoreskippedcluster -o uuid,name,vg_name,attr,size,seg_start_pe,devices,tags 2fec15c6-8f63-4a8b-ad94-00ddb9db625e (cwd None)
Thread-18100::DEBUG::2016-06-27 11:19:58,084::lvm::290::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  WARNING: lvmetad is running but disabled. Restart lvmetad before enabling it!\n'; <rc> = 0
Thread-18100::DEBUG::2016-06-27 11:19:58,085::lvm::462::Storage.LVM::(_reloadlvs) lvs reloaded
Thread-18100::DEBUG::2016-06-27 11:19:58,085::lvm::462::Storage.OperationMutex::(_reloadlvs) Operation 'lvm reload operation' released the operation mutex
Thread-18100::INFO::2016-06-27 11:19:58,085::logUtils::51::dispatcher::(wrapper) Run and protect: prepareImage, Return response: {'info': {'domainID': u'2fec15c6-8f63-4a8b-ad94-00ddb9db625e', 'volType': 'path', 'leaseOffset': 116391936, 'path': u'/rhev/data-center/mnt/blockSD/2fec15c6-8f63-4a8b-ad94-00ddb9db625e/images/22648231-5420-4f7f-a81b-d57f7b98da77/3c492e23-5cf9-4d13-89c5-74268076f234', 'volumeID': '3c492e23-5cf9-4d13-89c5-74268076f234', 'leasePath': '/dev/2fec15c6-8f63-4a8b-ad94-00ddb9db625e/leases', 'imageID': u'22648231-5420-4f7f-a81b-d57f7b98da77'}, 'path': u'/rhev/data-center/91958960-de08-4eb5-b8ab-92ba066dfda0/2fec15c6-8f63-4a8b-ad94-00ddb9db625e/images/22648231-5420-4f7f-a81b-d57f7b98da77/3c492e23-5cf9-4d13-89c5-74268076f234', 'imgVolumesInfo': [{'domainID': u'2fec15c6-8f63-4a8b-ad94-00ddb9db625e', 'volType': 'path', 'leaseOffset': 116391936, 'path': u'/rhev/data-center/mnt/blockSD/2fec15c6-8f63-4a8b-ad94-00ddb9db625e/images/22648231-5420-4f7f-a81b-d57f7b98da77/3c492e23-5cf9-4d13-89c5-74268076f234', 'volumeID': '3c492e23-5cf9-4d13-89c5-74268076f234', 'leasePath': '/dev/2fec15c6-8f63-4a8b-ad94-00ddb9db625e/leases', 'imageID': u'22648231-5420-4f7f-a81b-d57f7b98da77'}]}
Thread-18100::DEBUG::2016-06-27 11:19:58,085::task::1191::Storage.TaskManager.Task::(prepare) Task=`9009aa95-304b-4757-8e0c-55f73bff16f3`::finished: {'info': {'domainID': u'2fec15c6-8f63-4a8b-ad94-00ddb9db625e', 'volType': 'path', 'leaseOffset': 116391936, 'path': u'/rhev/data-center/mnt/blockSD/2fec15c6-8f63-4a8b-ad94-00ddb9db625e/images/22648231-5420-4f7f-a81b-d57f7b98da77/3c492e23-5cf9-4d13-89c5-74268076f234', 'volumeID': '3c492e23-5cf9-4d13-89c5-74268076f234', 'leasePath': '/dev/2fec15c6-8f63-4a8b-ad94-00ddb9db625e/leases', 'imageID': u'22648231-5420-4f7f-a81b-d57f7b98da77'}, 'path': u'/rhev/data-center/91958960-de08-4eb5-b8ab-92ba066dfda0/2fec15c6-8f63-4a8b-ad94-00ddb9db625e/images/22648231-5420-4f7f-a81b-d57f7b98da77/3c492e23-5cf9-4d13-89c5-74268076f234', 'imgVolumesInfo': [{'domainID': u'2fec15c6-8f63-4a8b-ad94-00ddb9db625e', 'volType': 'path', 'leaseOffset': 116391936, 'path': u'/rhev/data-center/mnt/blockSD/2fec15c6-8f63-4a8b-ad94-00ddb9db625e/images/22648231-5420-4f7f-a81b-d57f7b98da77/3c492e23-5cf9-4d13-89c5-74268076f234', 'volumeID': '3c492e23-5cf9-4d13-89c5-74268076f234', 'leasePath': '/dev/2fec15c6-8f63-4a8b-ad94-00ddb9db625e/leases', 'imageID': u'22648231-5420-4f7f-a81b-d57f7b98da77'}]}
Thread-18100::DEBUG::2016-06-27 11:19:58,085::task::595::Storage.TaskManager.Task::(_updateState) Task=`9009aa95-304b-4757-8e0c-55f73bff16f3`::moving from state preparing -> state finished
Thread-18100::DEBUG::2016-06-27 11:19:58,085::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {u'Storage.2fec15c6-8f63-4a8b-ad94-00ddb9db625e': < ResourceRef 'Storage.2fec15c6-8f63-4a8b-ad94-00ddb9db625e', isValid: 'True' obj: 'None'>}
Thread-18100::DEBUG::2016-06-27 11:19:58,086::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-18100::DEBUG::2016-06-27 11:19:58,086::resourceManager::619::Storage.ResourceManager::(releaseResource) Trying to release resource 'Storage.2fec15c6-8f63-4a8b-ad94-00ddb9db625e'
Thread-18100::DEBUG::2016-06-27 11:19:58,086::resourceManager::638::Storage.ResourceManager::(releaseResource) Released resource 'Storage.2fec15c6-8f63-4a8b-ad94-00ddb9db625e' (0 active users)
Thread-18100::DEBUG::2016-06-27 11:19:58,086::resourceManager::644::Storage.ResourceManager::(releaseResource) Resource 'Storage.2fec15c6-8f63-4a8b-ad94-00ddb9db625e' is free, finding out if anyone is waiting for it.
Thread-18100::DEBUG::2016-06-27 11:19:58,086::resourceManager::652::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'Storage.2fec15c6-8f63-4a8b-ad94-00ddb9db625e', Clearing records.
Thread-18100::DEBUG::2016-06-27 11:19:58,086::task::993::Storage.TaskManager.Task::(_decref) Task=`9009aa95-304b-4757-8e0c-55f73bff16f3`::ref 0 aborting False
Thread-18100::INFO::2016-06-27 11:19:58,086::clientIF::375::vds::(prepareVolumePath) prepared volume path: /rhev/data-center/91958960-de08-4eb5-b8ab-92ba066dfda0/2fec15c6-8f63-4a8b-ad94-00ddb9db625e/images/22648231-5420-4f7f-a81b-d57f7b98da77/3c492e23-5cf9-4d13-89c5-74268076f234
Thread-18100::DEBUG::2016-06-27 11:19:58,089::core::51::virt.vm::(__init__) vmId=`25267411-1ec2-4220-82dc-4ae048255fb0`::Ignoring param (target, 1048576) in Balloon
Thread-18100::INFO::2016-06-27 11:19:58,097::vm::1932::virt.vm::(_run) vmId=`25267411-1ec2-4220-82dc-4ae048255fb0`::<?xml version="1.0" encoding="utf-8"?>
<domain type="kvm" xmlns:ovirt="http://ovirt.org/vm/tune/1.0">
	<name>TestVM_Amestris</name>
	<uuid>25267411-1ec2-4220-82dc-4ae048255fb0</uuid>
	<memory>1048576</memory>
	<currentMemory>1048576</currentMemory>
	<maxMemory slots="16">4294967296</maxMemory>
	<vcpu current="4">32</vcpu>
	<devices>
		<channel type="unix">
			<target name="com.redhat.rhevm.vdsm" type="virtio"/>
			<source mode="bind" path="/var/lib/libvirt/qemu/channels/25267411-1ec2-4220-82dc-4ae048255fb0.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/25267411-1ec2-4220-82dc-4ae048255fb0.org.qemu.guest_agent.0"/>
		</channel>
		<input bus="ps2" type="mouse"/>
		<memballoon model="virtio">
			<address bus="0x00" domain="0x0000" function="0x0" slot="0x06" type="pci"/>
		</memballoon>
		<controller index="0" ports="16" type="virtio-serial">
			<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" ram="65536" type="qxl" vram="32768"/>
		</video>
		<graphics autoport="yes" passwd="*****" passwdValidTo="1970-01-01T00:00:01" port="-1" tlsPort="-1" type="spice">
			<listen network="vdsm-ovirtmgmt" type="network"/>
		</graphics>
		<interface type="bridge">
			<address bus="0x00" domain="0x0000" function="0x0" slot="0x07" type="pci"/>
			<mac address="00:1a:4a:16:01:55"/>
			<model type="virtio"/>
			<source bridge="ovirtmgmt"/>
			<filterref filter="vdsm-no-mac-spoofing"/>
			<link state="up"/>
			<bandwidth/>
		</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/>
		</disk>
		<disk device="disk" snapshot="no" type="block">
			<address bus="0x00" domain="0x0000" function="0x0" slot="0x05" type="pci"/>
			<source dev="/rhev/data-center/91958960-de08-4eb5-b8ab-92ba066dfda0/2fec15c6-8f63-4a8b-ad94-00ddb9db625e/images/22648231-5420-4f7f-a81b-d57f7b98da77/3c492e23-5cf9-4d13-89c5-74268076f234"/>
			<target bus="virtio" dev="vda"/>
			<serial>22648231-5420-4f7f-a81b-d57f7b98da77</serial>
			<boot order="1"/>
			<driver cache="none" error_policy="stop" io="native" name="qemu" type="raw"/>
		</disk>
		<channel type="spicevmc">
			<target name="com.redhat.spice.0" type="virtio"/>
		</channel>
	</devices>
	<metadata>
		<ovirt:qos/>
	</metadata>
	<os>
		<type arch="x86_64" machine="pc-i440fx-rhel7.2.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">7-2.1511.el7.centos.2.10</entry>
			<entry name="serial">FEA21725-A671-E511-AA32-0894EF035E60</entry>
			<entry name="uuid">25267411-1ec2-4220-82dc-4ae048255fb0</entry>
		</system>
	</sysinfo>
	<clock adjustment="0" offset="variable">
		<timer name="rtc" tickpolicy="catchup"/>
		<timer name="pit" tickpolicy="delay"/>
		<timer name="hpet" present="no"/>
	</clock>
	<features>
		<acpi/>
	</features>
	<cpu match="exact">
		<model>Haswell-noTSX</model>
		<topology cores="2" sockets="16" threads="1"/>
		<numa>
			<cell cpus="0,1,2,3" memory="1048576"/>
		</numa>
	</cpu>
	<numatune>
		<memory mode="interleave" nodeset="1,0"/>
	</numatune>
</domain>

Thread-1124::DEBUG::2016-06-27 11:19:58,413::blockSD::422::Storage.Misc.excCmd::(getReadDelay) /usr/bin/taskset --cpu-list 0-31 /usr/bin/dd if=/dev/2fec15c6-8f63-4a8b-ad94-00ddb9db625e/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-1124::DEBUG::2016-06-27 11:19:58,425::blockSD::422::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000664369 s, 6.2 MB/s\n'; <rc> = 0
libvirtEventLoop::DEBUG::2016-06-27 11:19:58,628::vm::4636::virt.vm::(onLibvirtLifecycleEvent) vmId=`25267411-1ec2-4220-82dc-4ae048255fb0`::event Resumed detail 0 opaque None
libvirtEventLoop::INFO::2016-06-27 11:19:58,628::vm::5157::virt.vm::(_logGuestCpuStatus) vmId=`25267411-1ec2-4220-82dc-4ae048255fb0`::CPU running: onResume
libvirtEventLoop::DEBUG::2016-06-27 11:19:58,632::vm::4636::virt.vm::(onLibvirtLifecycleEvent) vmId=`25267411-1ec2-4220-82dc-4ae048255fb0`::event Started detail 0 opaque None
Thread-18100::DEBUG::2016-06-27 11:19:58,642::vm::4431::virt.vm::(_getUnderlyingDriveInfo) vmId=`25267411-1ec2-4220-82dc-4ae048255fb0`::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-18100::DEBUG::2016-06-27 11:19:58,642::vm::4452::virt.vm::(_getUnderlyingDriveInfo) vmId=`25267411-1ec2-4220-82dc-4ae048255fb0`::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-18100::DEBUG::2016-06-27 11:19:58,642::vm::4472::virt.vm::(_getUnderlyingDriveInfo) vmId=`25267411-1ec2-4220-82dc-4ae048255fb0`::Matched {'name': (u'hdc', None), 'bootOrder': ('', None), 'boot': ([], None), 'readonly': (True, None), 'address': ({u'bus': u'1', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'0'}, None), 'path': ('', None), 'type': (u'cdrom', None)}
Thread-18100::DEBUG::2016-06-27 11:19:58,642::vm::4431::virt.vm::(_getUnderlyingDriveInfo) vmId=`25267411-1ec2-4220-82dc-4ae048255fb0`::Looking for drive with attributes {'name': u'vda', 'bootOrder': u'1', 'boot': [<DOM Element: boot at 0x7fc958350cf8>], 'readonly': False, 'address': {u'slot': u'0x05', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, 'path': u'/rhev/data-center/91958960-de08-4eb5-b8ab-92ba066dfda0/2fec15c6-8f63-4a8b-ad94-00ddb9db625e/images/22648231-5420-4f7f-a81b-d57f7b98da77/3c492e23-5cf9-4d13-89c5-74268076f234', 'type': u'disk'}
Thread-18100::DEBUG::2016-06-27 11:19:58,642::vm::4452::virt.vm::(_getUnderlyingDriveInfo) vmId=`25267411-1ec2-4220-82dc-4ae048255fb0`::Matched {'name': (u'vda', u'vda'), 'bootOrder': (u'1', u'1'), 'boot': ([<DOM Element: boot at 0x7fc958350cf8>], None), 'readonly': (False, False), 'address': ({u'slot': u'0x05', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, {u'slot': u'0x05', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}), 'path': (u'/rhev/data-center/91958960-de08-4eb5-b8ab-92ba066dfda0/2fec15c6-8f63-4a8b-ad94-00ddb9db625e/images/22648231-5420-4f7f-a81b-d57f7b98da77/3c492e23-5cf9-4d13-89c5-74268076f234', u'/rhev/data-center/91958960-de08-4eb5-b8ab-92ba066dfda0/2fec15c6-8f63-4a8b-ad94-00ddb9db625e/images/22648231-5420-4f7f-a81b-d57f7b98da77/3c492e23-5cf9-4d13-89c5-74268076f234'), 'type': (u'disk', u'disk')}
Thread-18100::DEBUG::2016-06-27 11:19:58,642::vm::4472::virt.vm::(_getUnderlyingDriveInfo) vmId=`25267411-1ec2-4220-82dc-4ae048255fb0`::Matched {'name': (u'vda', None), 'bootOrder': (u'1', None), 'boot': ([<DOM Element: boot at 0x7fc958350cf8>], None), 'readonly': (False, None), 'address': ({u'slot': u'0x05', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, None), 'path': (u'/rhev/data-center/91958960-de08-4eb5-b8ab-92ba066dfda0/2fec15c6-8f63-4a8b-ad94-00ddb9db625e/images/22648231-5420-4f7f-a81b-d57f7b98da77/3c492e23-5cf9-4d13-89c5-74268076f234', None), 'type': (u'disk', None)}
Thread-18100::DEBUG::2016-06-27 11:19:58,646::vmchannels::218::vds::(register) Add fileno 36 to listener's channels.
Thread-18100::INFO::2016-06-27 11:19:58,647::vm::5157::virt.vm::(_logGuestCpuStatus) vmId=`25267411-1ec2-4220-82dc-4ae048255fb0`::CPU running: domain initialization
Thread-18100::DEBUG::2016-06-27 11:19:58,666::__init__::206::jsonrpc.Notification::(emit) Sending event {"params": {"notify_time": 13350440690, "25267411-1ec2-4220-82dc-4ae048255fb0": {"status": "Powering up", "displayInfo": [{"tlsPort": "5907", "ipAddress": "10.40.150.221", "type": "spice", "port": "5906"}], "hash": "2735878772337449411", "displayIp": "10.40.150.221", "displayPort": "5906", "displaySecurePort": "5907", "timeOffset": "0", "pauseCode": "NOERR", "vcpuQuota": "-1", "cpuUser": "0.00", "monitorResponse": "0", "elapsedTime": "1", "displayType": "qxl", "cpuSys": "0.00", "clientIp": "", "vcpuPeriod": 100000}}, "jsonrpc": "2.0", "method": "|virt|VM_status|25267411-1ec2-4220-82dc-4ae048255fb0"}
VM Channels Listener::DEBUG::2016-06-27 11:19:58,819::vmchannels::125::vds::(_do_add_channels) fileno 36 was added to unconnected channels.
VM Channels Listener::DEBUG::2016-06-27 11:19:58,819::guestagent::225::virt.vm::(_connect) vmId=`25267411-1ec2-4220-82dc-4ae048255fb0`::Attempting connection to /var/lib/libvirt/qemu/channels/25267411-1ec2-4220-82dc-4ae048255fb0.com.redhat.rhevm.vdsm
VM Channels Listener::DEBUG::2016-06-27 11:19:58,820::guestagent::228::virt.vm::(_connect) vmId=`25267411-1ec2-4220-82dc-4ae048255fb0`::Connected to /var/lib/libvirt/qemu/channels/25267411-1ec2-4220-82dc-4ae048255fb0.com.redhat.rhevm.vdsm
VM Channels Listener::DEBUG::2016-06-27 11:19:58,820::vmchannels::166::vds::(_handle_unconnected) Connecting to fileno 36 succeeded.
Reactor thread::INFO::2016-06-27 11:19:58,986::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:53659
Reactor thread::DEBUG::2016-06-27 11:19:58,991::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11
Reactor thread::INFO::2016-06-27 11:19:58,991::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:53659
Reactor thread::DEBUG::2016-06-27 11:19:58,991::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 53659)
BindingXMLRPC::INFO::2016-06-27 11:19:58,992::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:53659
Thread-18102::INFO::2016-06-27 11:19:58,992::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:53659 started
Thread-18102::INFO::2016-06-27 11:19:59,000::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:53659 stopped
jsonrpc.Executor/5::DEBUG::2016-06-27 11:19:59,704::__init__::503::jsonrpc.JsonRpcServer::(_serveRequest) Calling 'Host.getVMFullList' in bridge with {u'vmList': [u'25267411-1ec2-4220-82dc-4ae048255fb0']}
jsonrpc.Executor/5::DEBUG::2016-06-27 11:19:59,705::__init__::533::jsonrpc.JsonRpcServer::(_serveRequest) Return 'Host.getVMFullList' in bridge with [{u'acpiEnable': u'true', u'emulatedMachine': u'pc-i440fx-rhel7.2.0', 'pid': '30901', u'memGuaranteedSize': 682, u'transparentHugePages': u'true', 'displayPort': u'5906', 'displaySecurePort': u'5907', u'spiceSslCipherSuite': u'DEFAULT', u'cpuType': u'Haswell-noTSX', u'smp': u'4', 'pauseCode': 'NOERR', u'guestNumaNodes': [{u'nodeIndex': 0, u'cpus': u'0,1,2,3', u'memory': u'1024'}], u'smartcardEnable': u'false', u'numaTune': {u'nodeset': u'1,0', u'mode': u'interleave'}, u'custom': {u'device_8c35d886-872f-4dc1-9464-2efee62137a4device_5586a2bf-f164-4fe2-8335-088a9109f44e': u"VmDevice:{id='VmDeviceId:{deviceId='5586a2bf-f164-4fe2-8335-088a9109f44e', vmId='25267411-1ec2-4220-82dc-4ae048255fb0'}', device='unix', type='CHANNEL', bootOrder='0', specParams='[]', address='{bus=0, controller=0, type=virtio-serial, port=1}', managed='false', plugged='true', readOnly='false', deviceAlias='channel0', customProperties='[]', snapshotId='null', logicalName='null', usingScsiReservation='false'}", u'device_8c35d886-872f-4dc1-9464-2efee62137a4device_5586a2bf-f164-4fe2-8335-088a9109f44edevice_e637898d-11e8-4bf5-b301-c33d78167c1ddevice_d7d04f26-05f3-4e9c-8d97-6af15a80591f': u"VmDevice:{id='VmDeviceId:{deviceId='d7d04f26-05f3-4e9c-8d97-6af15a80591f', vmId='25267411-1ec2-4220-82dc-4ae048255fb0'}', device='spicevmc', type='CHANNEL', bootOrder='0', specParams='[]', address='{bus=0, controller=0, type=virtio-serial, port=3}', managed='false', plugged='true', readOnly='false', deviceAlias='channel2', customProperties='[]', snapshotId='null', logicalName='null', usingScsiReservation='false'}", u'device_8c35d886-872f-4dc1-9464-2efee62137a4': u"VmDevice:{id='VmDeviceId:{deviceId='8c35d886-872f-4dc1-9464-2efee62137a4', vmId='25267411-1ec2-4220-82dc-4ae048255fb0'}', device='ide', type='CONTROLLER', bootOrder='0', specParams='[]', address='{slot=0x01, bus=0x00, domain=0x0000, type=pci, function=0x1}', managed='false', plugged='true', readOnly='false', deviceAlias='ide', customProperties='[]', snapshotId='null', logicalName='null', usingScsiReservation='false'}", u'device_8c35d886-872f-4dc1-9464-2efee62137a4device_5586a2bf-f164-4fe2-8335-088a9109f44edevice_e637898d-11e8-4bf5-b301-c33d78167c1d': u"VmDevice:{id='VmDeviceId:{deviceId='e637898d-11e8-4bf5-b301-c33d78167c1d', vmId='25267411-1ec2-4220-82dc-4ae048255fb0'}', device='unix', type='CHANNEL', bootOrder='0', specParams='[]', address='{bus=0, controller=0, type=virtio-serial, port=2}', managed='false', plugged='true', readOnly='false', deviceAlias='channel1', customProperties='[]', snapshotId='null', logicalName='null', usingScsiReservation='false'}"}, u'vmType': u'kvm', u'memSize': 1024, u'smpCoresPerSocket': u'2', u'vmName': u'TestVM_Amestris', u'nice': u'0', 'status': 'Up', u'maxMemSize': 4194304, u'bootMenuEnable': u'false', u'vmId': u'25267411-1ec2-4220-82dc-4ae048255fb0', u'copyPasteEnable': u'true', 'displayIp': '10.40.150.221', u'smpThreadsPerCore': u'1', 'guestDiskMapping': {}, u'spiceSecureChannels': u'smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard', u'fileTransferEnable': u'true', 'nicModel': 'rtl8139,pv', u'keyboardLayout': u'en-us', u'kvmEnable': u'true', u'pitReinjection': u'false', u'displayNetwork': u'ovirtmgmt', u'devices': [{'target': 1048576, u'specParams': {u'model': u'virtio'}, 'alias': u'balloon0', 'deviceType': u'balloon', u'deviceId': u'dcf132ee-5b8e-4d4b-a160-19aeea5b7e50', u'address': {u'function': u'0x0', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'slot': u'0x06'}, u'device': u'memballoon', u'type': u'balloon'}, {u'specParams': {}, 'alias': u'virtio-serial0', 'deviceType': u'controller', u'deviceId': u'7787219c-b86d-4e80-ad23-bb95c97730d5', u'address': {u'slot': u'0x04', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, u'device': u'virtio-serial', u'type': u'controller'}, {u'specParams': {u'vram': u'32768', u'ram': u'65536', u'heads': u'1'}, 'alias': u'video0', 'deviceType': u'video', u'deviceId': u'0ffeff5c-19bb-44c0-8107-447779a672c8', u'address': {u'slot': u'0x02', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, u'device': u'qxl', u'type': u'video'}, {'tlsPort': u'5907', u'specParams': {u'fileTransferEnable': u'true', u'copyPasteEnable': u'true', 'displayIp': '10.40.150.221', 'displayNetwork': u'ovirtmgmt'}, 'deviceType': u'graphics', u'deviceId': u'2b5a92d5-6d46-4a7f-b781-e277260fa1c5', u'device': u'spice', u'type': u'graphics', 'port': u'5906'}, {u'nicModel': u'pv', u'macAddr': u'00:1a:4a:16:01:55', u'linkActive': True, u'network': u'ovirtmgmt', u'specParams': {u'inbound': {}, u'outbound': {}}, u'filter': u'vdsm-no-mac-spoofing', 'alias': u'net0', 'deviceType': u'interface', u'deviceId': u'5ecd077b-15bf-44b6-855e-039ebec8f0bf', u'address': {u'slot': u'0x07', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, u'device': u'bridge', u'type': u'interface', 'name': u'vnet3'}, {u'index': u'2', u'iface': u'ide', 'name': u'hdc', 'alias': u'ide0-1-0', u'specParams': {u'path': u''}, u'readonly': 'True', 'deviceType': u'disk', u'deviceId': u'8e35d253-df2f-4920-b8d8-2a29735d148c', u'address': {u'bus': u'1', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'0'}, u'device': u'cdrom', u'shared': u'false', u'path': '', u'type': u'disk'}, {u'poolID': u'91958960-de08-4eb5-b8ab-92ba066dfda0', 'reqsize': '0', u'index': 0, u'iface': u'virtio', 'apparentsize': '26843545600', u'specParams': {}, u'imageID': u'22648231-5420-4f7f-a81b-d57f7b98da77', u'readonly': 'False', 'deviceType': u'disk', u'shared': u'false', 'truesize': '26843545600', u'type': u'disk', u'domainID': u'2fec15c6-8f63-4a8b-ad94-00ddb9db625e', 'volumeInfo': {'domainID': u'2fec15c6-8f63-4a8b-ad94-00ddb9db625e', 'volType': 'path', 'leaseOffset': 116391936, 'volumeID': '3c492e23-5cf9-4d13-89c5-74268076f234', 'leasePath': '/dev/2fec15c6-8f63-4a8b-ad94-00ddb9db625e/leases', 'imageID': u'22648231-5420-4f7f-a81b-d57f7b98da77', 'path': u'/rhev/data-center/mnt/blockSD/2fec15c6-8f63-4a8b-ad94-00ddb9db625e/images/22648231-5420-4f7f-a81b-d57f7b98da77/3c492e23-5cf9-4d13-89c5-74268076f234'}, u'format': u'raw', u'deviceId': u'22648231-5420-4f7f-a81b-d57f7b98da77', u'address': {u'slot': u'0x05', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, u'device': u'disk', 'path': u'/rhev/data-center/91958960-de08-4eb5-b8ab-92ba066dfda0/2fec15c6-8f63-4a8b-ad94-00ddb9db625e/images/22648231-5420-4f7f-a81b-d57f7b98da77/3c492e23-5cf9-4d13-89c5-74268076f234', u'propagateErrors': u'off', u'optional': u'false', 'name': u'vda', u'bootOrder': u'1', u'volumeID': u'3c492e23-5cf9-4d13-89c5-74268076f234', 'alias': u'virtio-disk0', 'volumeChain': [{'domainID': u'2fec15c6-8f63-4a8b-ad94-00ddb9db625e', 'volType': 'path', 'leaseOffset': 116391936, 'volumeID': '3c492e23-5cf9-4d13-89c5-74268076f234', 'leasePath': '/dev/2fec15c6-8f63-4a8b-ad94-00ddb9db625e/leases', 'imageID': u'22648231-5420-4f7f-a81b-d57f7b98da77', 'path': u'/rhev/data-center/mnt/blockSD/2fec15c6-8f63-4a8b-ad94-00ddb9db625e/images/22648231-5420-4f7f-a81b-d57f7b98da77/3c492e23-5cf9-4d13-89c5-74268076f234'}]}, {'device': u'usb', 'alias': u'usb', 'deviceType': 'controller', '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'ide', 'deviceType': 'controller', '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'unix', 'alias': u'channel0', 'deviceType': u'channel', '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', 'deviceType': u'channel', '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', 'deviceType': u'channel', 'type': u'channel', 'address': {u'bus': u'0', u'controller': u'0', u'type': u'virtio-serial', u'port': u'3'}}], u'display': 'qxl', u'timeOffset': u'0', u'maxVCpus': u'32', 'clientIp': '', 'statusTime': '13350441730', u'maxMemSlots': 16}]
mailbox.SPMMonitor::DEBUG::2016-06-27 11:19:59,938::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) /usr/bin/taskset --cpu-list 0-31 dd if=/rhev/data-center/91958960-de08-4eb5-b8ab-92ba066dfda0/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000 (cwd None)
mailbox.SPMMonitor::DEBUG::2016-06-27 11:19:59,959::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0120406 s, 85.0 MB/s\n'; <rc> = 0
mailbox.SPMMonitor::DEBUG::2016-06-27 11:20:01,969::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) /usr/bin/taskset --cpu-list 0-31 dd if=/rhev/data-center/91958960-de08-4eb5-b8ab-92ba066dfda0/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000 (cwd None)
mailbox.SPMMonitor::DEBUG::2016-06-27 11:20:01,990::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0118478 s, 86.4 MB/s\n'; <rc> = 0
jsonrpc.Executor/3::DEBUG::2016-06-27 11:20:03,480::__init__::503::jsonrpc.JsonRpcServer::(_serveRequest) Calling 'StoragePool.getSpmStatus' in bridge with {u'storagepoolID': u'91958960-de08-4eb5-b8ab-92ba066dfda0'}
jsonrpc.Executor/3::DEBUG::2016-06-27 11:20:03,481::task::595::Storage.TaskManager.Task::(_updateState) Task=`7edb4eb7-5e9d-400c-aee0-aa254ff84621`::moving from state init -> state preparing
jsonrpc.Executor/3::INFO::2016-06-27 11:20:03,481::logUtils::48::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID=u'91958960-de08-4eb5-b8ab-92ba066dfda0', options=None)
jsonrpc.Executor/3::INFO::2016-06-27 11:20:03,495::logUtils::51::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 3, 'spmStatus': 'SPM', 'spmLver': 935L}}
jsonrpc.Executor/3::DEBUG::2016-06-27 11:20:03,495::task::1191::Storage.TaskManager.Task::(prepare) Task=`7edb4eb7-5e9d-400c-aee0-aa254ff84621`::finished: {'spm_st': {'spmId': 3, 'spmStatus': 'SPM', 'spmLver': 935L}}
jsonrpc.Executor/3::DEBUG::2016-06-27 11:20:03,495::task::595::Storage.TaskManager.Task::(_updateState) Task=`7edb4eb7-5e9d-400c-aee0-aa254ff84621`::moving from state preparing -> state finished
jsonrpc.Executor/3::DEBUG::2016-06-27 11:20:03,495::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
jsonrpc.Executor/3::DEBUG::2016-06-27 11:20:03,495::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
jsonrpc.Executor/3::DEBUG::2016-06-27 11:20:03,495::task::993::Storage.TaskManager.Task::(_decref) Task=`7edb4eb7-5e9d-400c-aee0-aa254ff84621`::ref 0 aborting False
jsonrpc.Executor/3::DEBUG::2016-06-27 11:20:03,495::__init__::533::jsonrpc.JsonRpcServer::(_serveRequest) Return 'StoragePool.getSpmStatus' in bridge with {'spmId': 3, 'spmStatus': 'SPM', 'spmLver': 935L}
mailbox.SPMMonitor::DEBUG::2016-06-27 11:20:03,998::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) /usr/bin/taskset --cpu-list 0-31 dd if=/rhev/data-center/91958960-de08-4eb5-b8ab-92ba066dfda0/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000 (cwd None)
mailbox.SPMMonitor::DEBUG::2016-06-27 11:20:04,019::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0118598 s, 86.3 MB/s\n'; <rc> = 0
jsonrpc.Executor/7::DEBUG::2016-06-27 11:20:04,503::__init__::503::jsonrpc.JsonRpcServer::(_serveRequest) Calling 'StoragePool.getInfo' in bridge with {u'storagepoolID': u'91958960-de08-4eb5-b8ab-92ba066dfda0'}
jsonrpc.Executor/7::DEBUG::2016-06-27 11:20:04,504::task::595::Storage.TaskManager.Task::(_updateState) Task=`9f1dd9da-e45b-49a6-82d2-c4877a6df09e`::moving from state init -> state preparing
jsonrpc.Executor/7::INFO::2016-06-27 11:20:04,504::logUtils::48::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID=u'91958960-de08-4eb5-b8ab-92ba066dfda0', options=None)
jsonrpc.Executor/7::DEBUG::2016-06-27 11:20:04,504::resourceManager::199::Storage.ResourceManager.Request::(__init__) ResName=`Storage.91958960-de08-4eb5-b8ab-92ba066dfda0`ReqID=`883cf4d8-3623-4950-be3c-2b56d6a42fea`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2642' at 'getStoragePoolInfo'
jsonrpc.Executor/7::DEBUG::2016-06-27 11:20:04,504::resourceManager::545::Storage.ResourceManager::(registerResource) Trying to register resource 'Storage.91958960-de08-4eb5-b8ab-92ba066dfda0' for lock type 'shared'
jsonrpc.Executor/7::DEBUG::2016-06-27 11:20:04,504::resourceManager::604::Storage.ResourceManager::(registerResource) Resource 'Storage.91958960-de08-4eb5-b8ab-92ba066dfda0' is free. Now locking as 'shared' (1 active user)
jsonrpc.Executor/7::DEBUG::2016-06-27 11:20:04,505::resourceManager::239::Storage.ResourceManager.Request::(grant) ResName=`Storage.91958960-de08-4eb5-b8ab-92ba066dfda0`ReqID=`883cf4d8-3623-4950-be3c-2b56d6a42fea`::Granted request
jsonrpc.Executor/7::DEBUG::2016-06-27 11:20:04,505::task::827::Storage.TaskManager.Task::(resourceAcquired) Task=`9f1dd9da-e45b-49a6-82d2-c4877a6df09e`::_resourcesAcquired: Storage.91958960-de08-4eb5-b8ab-92ba066dfda0 (shared)
jsonrpc.Executor/7::DEBUG::2016-06-27 11:20:04,505::task::993::Storage.TaskManager.Task::(_decref) Task=`9f1dd9da-e45b-49a6-82d2-c4877a6df09e`::ref 1 aborting False
jsonrpc.Executor/7::INFO::2016-06-27 11:20:04,517::logUtils::51::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'No Description', 'isoprefix': '', 'pool_status': 'connected', 'lver': 935L, 'domains': u'2fec15c6-8f63-4a8b-ad94-00ddb9db625e:Active', 'master_uuid': '2fec15c6-8f63-4a8b-ad94-00ddb9db625e', 'version': '3', 'spm_id': 3, 'type': 'ISCSI', 'master_ver': 2}, 'dominfo': {u'2fec15c6-8f63-4a8b-ad94-00ddb9db625e': {'status': u'Active', 'diskfree': '1864552677376', 'isoprefix': '', 'alerts': [], 'disktotal': '2198620602368', 'version': 3}}}
jsonrpc.Executor/7::DEBUG::2016-06-27 11:20:04,517::task::1191::Storage.TaskManager.Task::(prepare) Task=`9f1dd9da-e45b-49a6-82d2-c4877a6df09e`::finished: {'info': {'name': 'No Description', 'isoprefix': '', 'pool_status': 'connected', 'lver': 935L, 'domains': u'2fec15c6-8f63-4a8b-ad94-00ddb9db625e:Active', 'master_uuid': '2fec15c6-8f63-4a8b-ad94-00ddb9db625e', 'version': '3', 'spm_id': 3, 'type': 'ISCSI', 'master_ver': 2}, 'dominfo': {u'2fec15c6-8f63-4a8b-ad94-00ddb9db625e': {'status': u'Active', 'diskfree': '1864552677376', 'isoprefix': '', 'alerts': [], 'disktotal': '2198620602368', 'version': 3}}}
jsonrpc.Executor/7::DEBUG::2016-06-27 11:20:04,517::task::595::Storage.TaskManager.Task::(_updateState) Task=`9f1dd9da-e45b-49a6-82d2-c4877a6df09e`::moving from state preparing -> state finished
jsonrpc.Executor/7::DEBUG::2016-06-27 11:20:04,517::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {u'Storage.91958960-de08-4eb5-b8ab-92ba066dfda0': < ResourceRef 'Storage.91958960-de08-4eb5-b8ab-92ba066dfda0', isValid: 'True' obj: 'None'>}
jsonrpc.Executor/7::DEBUG::2016-06-27 11:20:04,517::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
jsonrpc.Executor/7::DEBUG::2016-06-27 11:20:04,517::resourceManager::619::Storage.ResourceManager::(releaseResource) Trying to release resource 'Storage.91958960-de08-4eb5-b8ab-92ba066dfda0'
jsonrpc.Executor/7::DEBUG::2016-06-27 11:20:04,518::resourceManager::638::Storage.ResourceManager::(releaseResource) Released resource 'Storage.91958960-de08-4eb5-b8ab-92ba066dfda0' (0 active users)
jsonrpc.Executor/7::DEBUG::2016-06-27 11:20:04,518::resourceManager::644::Storage.ResourceManager::(releaseResource) Resource 'Storage.91958960-de08-4eb5-b8ab-92ba066dfda0' is free, finding out if anyone is waiting for it.
jsonrpc.Executor/7::DEBUG::2016-06-27 11:20:04,518::resourceManager::652::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'Storage.91958960-de08-4eb5-b8ab-92ba066dfda0', Clearing records.
jsonrpc.Executor/7::DEBUG::2016-06-27 11:20:04,518::task::993::Storage.TaskManager.Task::(_decref) Task=`9f1dd9da-e45b-49a6-82d2-c4877a6df09e`::ref 0 aborting False
jsonrpc.Executor/7::DEBUG::2016-06-27 11:20:04,518::__init__::533::jsonrpc.JsonRpcServer::(_serveRequest) Return 'StoragePool.getInfo' in bridge with {'info': {'name': 'No Description', 'isoprefix': '', 'pool_status': 'connected', 'lver': 935L, 'domains': u'2fec15c6-8f63-4a8b-ad94-00ddb9db625e:Active', 'master_uuid': '2fec15c6-8f63-4a8b-ad94-00ddb9db625e', 'version': '3', 'spm_id': 3, 'type': 'ISCSI', 'master_ver': 2}, 'dominfo': {u'2fec15c6-8f63-4a8b-ad94-00ddb9db625e': {'status': u'Active', 'diskfree': '1864552677376', 'isoprefix': '', 'alerts': [], 'disktotal': '2198620602368', 'version': 3}}}
mailbox.SPMMonitor::DEBUG::2016-06-27 11:20:06,029::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) /usr/bin/taskset --cpu-list 0-31 dd if=/rhev/data-center/91958960-de08-4eb5-b8ab-92ba066dfda0/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000 (cwd None)
mailbox.SPMMonitor::DEBUG::2016-06-27 11:20:06,050::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0122189 s, 83.8 MB/s\n'; <rc> = 0
mailbox.SPMMonitor::DEBUG::2016-06-27 11:20:08,060::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) /usr/bin/taskset --cpu-list 0-31 dd if=/rhev/data-center/91958960-de08-4eb5-b8ab-92ba066dfda0/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000 (cwd None)
mailbox.SPMMonitor::DEBUG::2016-06-27 11:20:08,081::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0123316 s, 83.0 MB/s\n'; <rc> = 0
Thread-1124::DEBUG::2016-06-27 11:20:08,430::blockSD::422::Storage.Misc.excCmd::(getReadDelay) /usr/bin/taskset --cpu-list 0-31 /usr/bin/dd if=/dev/2fec15c6-8f63-4a8b-ad94-00ddb9db625e/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-1124::DEBUG::2016-06-27 11:20:08,439::blockSD::422::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000673121 s, 6.1 MB/s\n'; <rc> = 0
mailbox.SPMMonitor::DEBUG::2016-06-27 11:20:10,091::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) /usr/bin/taskset --cpu-list 0-31 dd if=/rhev/data-center/91958960-de08-4eb5-b8ab-92ba066dfda0/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000 (cwd None)
mailbox.SPMMonitor::DEBUG::2016-06-27 11:20:10,111::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0117959 s, 86.8 MB/s\n'; <rc> = 0
jsonrpc.Executor/0::DEBUG::2016-06-27 11:20:10,453::task::595::Storage.TaskManager.Task::(_updateState) Task=`8e2db3c6-26fe-43d6-b9e6-194ed3fca950`::moving from state init -> state preparing
jsonrpc.Executor/0::INFO::2016-06-27 11:20:10,453::logUtils::48::dispatcher::(wrapper) Run and protect: repoStats(options=None)
jsonrpc.Executor/0::INFO::2016-06-27 11:20:10,453::logUtils::51::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'2fec15c6-8f63-4a8b-ad94-00ddb9db625e': {'code': 0, 'actual': True, 'version': 3, 'acquired': True, 'delay': '0.000673121', 'lastCheck': '2.0', 'valid': True}}
jsonrpc.Executor/0::DEBUG::2016-06-27 11:20:10,453::task::1191::Storage.TaskManager.Task::(prepare) Task=`8e2db3c6-26fe-43d6-b9e6-194ed3fca950`::finished: {u'2fec15c6-8f63-4a8b-ad94-00ddb9db625e': {'code': 0, 'actual': True, 'version': 3, 'acquired': True, 'delay': '0.000673121', 'lastCheck': '2.0', 'valid': True}}
jsonrpc.Executor/0::DEBUG::2016-06-27 11:20:10,453::task::595::Storage.TaskManager.Task::(_updateState) Task=`8e2db3c6-26fe-43d6-b9e6-194ed3fca950`::moving from state preparing -> state finished
jsonrpc.Executor/0::DEBUG::2016-06-27 11:20:10,454::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
jsonrpc.Executor/0::DEBUG::2016-06-27 11:20:10,454::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
jsonrpc.Executor/0::DEBUG::2016-06-27 11:20:10,454::task::993::Storage.TaskManager.Task::(_decref) Task=`8e2db3c6-26fe-43d6-b9e6-194ed3fca950`::ref 0 aborting False
libvirtEventLoop::INFO::2016-06-27 11:20:10,925::vm::3787::virt.vm::(onIOError) vmId=`25267411-1ec2-4220-82dc-4ae048255fb0`::abnormal vm stop device virtio-disk0 error eio
libvirtEventLoop::INFO::2016-06-27 11:20:10,925::vm::5157::virt.vm::(_logGuestCpuStatus) vmId=`25267411-1ec2-4220-82dc-4ae048255fb0`::CPU stopped: onIOError
libvirtEventLoop::DEBUG::2016-06-27 11:20:10,925::__init__::206::jsonrpc.Notification::(emit) Sending event {"params": {"notify_time": 13350452950, "25267411-1ec2-4220-82dc-4ae048255fb0": {"status": "Paused", "ioerror": {"alias": "virtio-disk0", "name": "vda", "path": "/rhev/data-center/91958960-de08-4eb5-b8ab-92ba066dfda0/2fec15c6-8f63-4a8b-ad94-00ddb9db625e/images/22648231-5420-4f7f-a81b-d57f7b98da77/3c492e23-5cf9-4d13-89c5-74268076f234"}, "pauseCode": "EIO"}}, "jsonrpc": "2.0", "method": "|virt|VM_status|25267411-1ec2-4220-82dc-4ae048255fb0"}
libvirtEventLoop::DEBUG::2016-06-27 11:20:10,926::vm::4636::virt.vm::(onLibvirtLifecycleEvent) vmId=`25267411-1ec2-4220-82dc-4ae048255fb0`::event Suspended detail 2 opaque None
libvirtEventLoop::INFO::2016-06-27 11:20:10,926::vm::5157::virt.vm::(_logGuestCpuStatus) vmId=`25267411-1ec2-4220-82dc-4ae048255fb0`::CPU stopped: onSuspend
mailbox.SPMMonitor::DEBUG::2016-06-27 11:20:12,121::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) /usr/bin/taskset --cpu-list 0-31 dd if=/rhev/data-center/91958960-de08-4eb5-b8ab-92ba066dfda0/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000 (cwd None)
mailbox.SPMMonitor::DEBUG::2016-06-27 11:20:12,146::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0133835 s, 76.5 MB/s\n'; <rc> = 0
Reactor thread::INFO::2016-06-27 11:20:14,016::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:53675
Reactor thread::DEBUG::2016-06-27 11:20:14,021::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11
Reactor thread::INFO::2016-06-27 11:20:14,021::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:53675
Reactor thread::DEBUG::2016-06-27 11:20:14,021::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 53675)
BindingXMLRPC::INFO::2016-06-27 11:20:14,022::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:53675
Thread-18103::INFO::2016-06-27 11:20:14,022::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:53675 started
Thread-18103::INFO::2016-06-27 11:20:14,030::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:53675 stopped
mailbox.SPMMonitor::DEBUG::2016-06-27 11:20:14,156::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) /usr/bin/taskset --cpu-list 0-31 dd if=/rhev/data-center/91958960-de08-4eb5-b8ab-92ba066dfda0/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000 (cwd None)
mailbox.SPMMonitor::DEBUG::2016-06-27 11:20:14,180::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0120775 s, 84.8 MB/s\n'; <rc> = 0
jsonrpc.Executor/6::DEBUG::2016-06-27 11:20:15,548::__init__::503::jsonrpc.JsonRpcServer::(_serveRequest) Calling 'StoragePool.getSpmStatus' in bridge with {u'storagepoolID': u'91958960-de08-4eb5-b8ab-92ba066dfda0'}
jsonrpc.Executor/6::DEBUG::2016-06-27 11:20:15,549::task::595::Storage.TaskManager.Task::(_updateState) Task=`241d94e1-d301-4df4-b0bb-69ce9959cd6c`::moving from state init -> state preparing
jsonrpc.Executor/6::INFO::2016-06-27 11:20:15,549::logUtils::48::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID=u'91958960-de08-4eb5-b8ab-92ba066dfda0', options=None)
jsonrpc.Executor/6::INFO::2016-06-27 11:20:15,564::logUtils::51::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 3, 'spmStatus': 'SPM', 'spmLver': 935L}}
jsonrpc.Executor/6::DEBUG::2016-06-27 11:20:15,564::task::1191::Storage.TaskManager.Task::(prepare) Task=`241d94e1-d301-4df4-b0bb-69ce9959cd6c`::finished: {'spm_st': {'spmId': 3, 'spmStatus': 'SPM', 'spmLver': 935L}}
jsonrpc.Executor/6::DEBUG::2016-06-27 11:20:15,564::task::595::Storage.TaskManager.Task::(_updateState) Task=`241d94e1-d301-4df4-b0bb-69ce9959cd6c`::moving from state preparing -> state finished
jsonrpc.Executor/6::DEBUG::2016-06-27 11:20:15,564::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
jsonrpc.Executor/6::DEBUG::2016-06-27 11:20:15,564::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
jsonrpc.Executor/6::DEBUG::2016-06-27 11:20:15,564::task::993::Storage.TaskManager.Task::(_decref) Task=`241d94e1-d301-4df4-b0bb-69ce9959cd6c`::ref 0 aborting False
jsonrpc.Executor/6::DEBUG::2016-06-27 11:20:15,564::__init__::533::jsonrpc.JsonRpcServer::(_serveRequest) Return 'StoragePool.getSpmStatus' in bridge with {'spmId': 3, 'spmStatus': 'SPM', 'spmLver': 935L}
mailbox.SPMMonitor::DEBUG::2016-06-27 11:20:16,193::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) /usr/bin/taskset --cpu-list 0-31 dd if=/rhev/data-center/91958960-de08-4eb5-b8ab-92ba066dfda0/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000 (cwd None)
mailbox.SPMMonitor::DEBUG::2016-06-27 11:20:16,217::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0125346 s, 81.7 MB/s\n'; <rc> = 0
jsonrpc.Executor/1::DEBUG::2016-06-27 11:20:16,574::__init__::503::jsonrpc.JsonRpcServer::(_serveRequest) Calling 'StoragePool.getInfo' in bridge with {u'storagepoolID': u'91958960-de08-4eb5-b8ab-92ba066dfda0'}
jsonrpc.Executor/1::DEBUG::2016-06-27 11:20:16,575::task::595::Storage.TaskManager.Task::(_updateState) Task=`6f19e3c5-0276-4724-9c0f-6b05bbf23b6e`::moving from state init -> state preparing
jsonrpc.Executor/1::INFO::2016-06-27 11:20:16,575::logUtils::48::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID=u'91958960-de08-4eb5-b8ab-92ba066dfda0', options=None)
jsonrpc.Executor/1::DEBUG::2016-06-27 11:20:16,575::resourceManager::199::Storage.ResourceManager.Request::(__init__) ResName=`Storage.91958960-de08-4eb5-b8ab-92ba066dfda0`ReqID=`23254dab-dc15-4c43-b6b7-d78cc0dee30d`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2642' at 'getStoragePoolInfo'
jsonrpc.Executor/1::DEBUG::2016-06-27 11:20:16,575::resourceManager::545::Storage.ResourceManager::(registerResource) Trying to register resource 'Storage.91958960-de08-4eb5-b8ab-92ba066dfda0' for lock type 'shared'
jsonrpc.Executor/1::DEBUG::2016-06-27 11:20:16,576::resourceManager::604::Storage.ResourceManager::(registerResource) Resource 'Storage.91958960-de08-4eb5-b8ab-92ba066dfda0' is free. Now locking as 'shared' (1 active user)
jsonrpc.Executor/1::DEBUG::2016-06-27 11:20:16,576::resourceManager::239::Storage.ResourceManager.Request::(grant) ResName=`Storage.91958960-de08-4eb5-b8ab-92ba066dfda0`ReqID=`23254dab-dc15-4c43-b6b7-d78cc0dee30d`::Granted request
jsonrpc.Executor/1::DEBUG::2016-06-27 11:20:16,576::task::827::Storage.TaskManager.Task::(resourceAcquired) Task=`6f19e3c5-0276-4724-9c0f-6b05bbf23b6e`::_resourcesAcquired: Storage.91958960-de08-4eb5-b8ab-92ba066dfda0 (shared)
jsonrpc.Executor/1::DEBUG::2016-06-27 11:20:16,576::task::993::Storage.TaskManager.Task::(_decref) Task=`6f19e3c5-0276-4724-9c0f-6b05bbf23b6e`::ref 1 aborting False
jsonrpc.Executor/1::INFO::2016-06-27 11:20:16,589::logUtils::51::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'No Description', 'isoprefix': '', 'pool_status': 'connected', 'lver': 935L, 'domains': u'2fec15c6-8f63-4a8b-ad94-00ddb9db625e:Active', 'master_uuid': '2fec15c6-8f63-4a8b-ad94-00ddb9db625e', 'version': '3', 'spm_id': 3, 'type': 'ISCSI', 'master_ver': 2}, 'dominfo': {u'2fec15c6-8f63-4a8b-ad94-00ddb9db625e': {'status': u'Active', 'diskfree': '1864552677376', 'isoprefix': '', 'alerts': [], 'disktotal': '2198620602368', 'version': 3}}}
jsonrpc.Executor/1::DEBUG::2016-06-27 11:20:16,589::task::1191::Storage.TaskManager.Task::(prepare) Task=`6f19e3c5-0276-4724-9c0f-6b05bbf23b6e`::finished: {'info': {'name': 'No Description', 'isoprefix': '', 'pool_status': 'connected', 'lver': 935L, 'domains': u'2fec15c6-8f63-4a8b-ad94-00ddb9db625e:Active', 'master_uuid': '2fec15c6-8f63-4a8b-ad94-00ddb9db625e', 'version': '3', 'spm_id': 3, 'type': 'ISCSI', 'master_ver': 2}, 'dominfo': {u'2fec15c6-8f63-4a8b-ad94-00ddb9db625e': {'status': u'Active', 'diskfree': '1864552677376', 'isoprefix': '', 'alerts': [], 'disktotal': '2198620602368', 'version': 3}}}
jsonrpc.Executor/1::DEBUG::2016-06-27 11:20:16,589::task::595::Storage.TaskManager.Task::(_updateState) Task=`6f19e3c5-0276-4724-9c0f-6b05bbf23b6e`::moving from state preparing -> state finished
jsonrpc.Executor/1::DEBUG::2016-06-27 11:20:16,589::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {u'Storage.91958960-de08-4eb5-b8ab-92ba066dfda0': < ResourceRef 'Storage.91958960-de08-4eb5-b8ab-92ba066dfda0', isValid: 'True' obj: 'None'>}
jsonrpc.Executor/1::DEBUG::2016-06-27 11:20:16,589::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
jsonrpc.Executor/1::DEBUG::2016-06-27 11:20:16,590::resourceManager::619::Storage.ResourceManager::(releaseResource) Trying to release resource 'Storage.91958960-de08-4eb5-b8ab-92ba066dfda0'
jsonrpc.Executor/1::DEBUG::2016-06-27 11:20:16,590::resourceManager::638::Storage.ResourceManager::(releaseResource) Released resource 'Storage.91958960-de08-4eb5-b8ab-92ba066dfda0' (0 active users)
jsonrpc.Executor/1::DEBUG::2016-06-27 11:20:16,590::resourceManager::644::Storage.ResourceManager::(releaseResource) Resource 'Storage.91958960-de08-4eb5-b8ab-92ba066dfda0' is free, finding out if anyone is waiting for it.
jsonrpc.Executor/1::DEBUG::2016-06-27 11:20:16,590::resourceManager::652::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'Storage.91958960-de08-4eb5-b8ab-92ba066dfda0', Clearing records.
jsonrpc.Executor/1::DEBUG::2016-06-27 11:20:16,590::task::993::Storage.TaskManager.Task::(_decref) Task=`6f19e3c5-0276-4724-9c0f-6b05bbf23b6e`::ref 0 aborting False
jsonrpc.Executor/1::DEBUG::2016-06-27 11:20:16,591::__init__::533::jsonrpc.JsonRpcServer::(_serveRequest) Return 'StoragePool.getInfo' in bridge with {'info': {'name': 'No Description', 'isoprefix': '', 'pool_status': 'connected', 'lver': 935L, 'domains': u'2fec15c6-8f63-4a8b-ad94-00ddb9db625e:Active', 'master_uuid': '2fec15c6-8f63-4a8b-ad94-00ddb9db625e', 'version': '3', 'spm_id': 3, 'type': 'ISCSI', 'master_ver': 2}, 'dominfo': {u'2fec15c6-8f63-4a8b-ad94-00ddb9db625e': {'status': u'Active', 'diskfree': '1864552677376', 'isoprefix': '', 'alerts': [], 'disktotal': '2198620602368', 'version': 3}}}
periodic/2::DEBUG::2016-06-27 11:20:18,135::task::595::Storage.TaskManager.Task::(_updateState) Task=`63f6a4c8-5f22-4f40-a448-7799b024a2e4`::moving from state init -> state preparing
periodic/2::INFO::2016-06-27 11:20:18,136::logUtils::48::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID=u'2fec15c6-8f63-4a8b-ad94-00ddb9db625e', spUUID=u'91958960-de08-4eb5-b8ab-92ba066dfda0', imgUUID=u'91511d8a-600d-4f5d-ab3e-fd3c424ec29a', volUUID=u'df4314d0-7805-479f-acac-fcf4c677ae53', options=None)
periodic/2::INFO::2016-06-27 11:20:18,136::logUtils::51::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '26843545600', 'apparentsize': '26843545600'}
periodic/2::DEBUG::2016-06-27 11:20:18,136::task::1191::Storage.TaskManager.Task::(prepare) Task=`63f6a4c8-5f22-4f40-a448-7799b024a2e4`::finished: {'truesize': '26843545600', 'apparentsize': '26843545600'}
periodic/2::DEBUG::2016-06-27 11:20:18,136::task::595::Storage.TaskManager.Task::(_updateState) Task=`63f6a4c8-5f22-4f40-a448-7799b024a2e4`::moving from state preparing -> state finished
periodic/2::DEBUG::2016-06-27 11:20:18,136::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
periodic/2::DEBUG::2016-06-27 11:20:18,136::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
periodic/2::DEBUG::2016-06-27 11:20:18,136::task::993::Storage.TaskManager.Task::(_decref) Task=`63f6a4c8-5f22-4f40-a448-7799b024a2e4`::ref 0 aborting False
periodic/1::DEBUG::2016-06-27 11:20:18,137::task::595::Storage.TaskManager.Task::(_updateState) Task=`66f32d63-2383-4fc6-89f3-8e79f5a33524`::moving from state init -> state preparing
periodic/1::INFO::2016-06-27 11:20:18,137::logUtils::48::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID=u'2fec15c6-8f63-4a8b-ad94-00ddb9db625e', spUUID=u'91958960-de08-4eb5-b8ab-92ba066dfda0', imgUUID=u'31ccb83b-6cf0-426f-8f75-fd6e07a59d12', volUUID=u'5abcac8e-970c-4dab-9852-fe61006ee72f', options=None)
periodic/1::INFO::2016-06-27 11:20:18,137::logUtils::51::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '26843545600', 'apparentsize': '26843545600'}
periodic/1::DEBUG::2016-06-27 11:20:18,137::task::1191::Storage.TaskManager.Task::(prepare) Task=`66f32d63-2383-4fc6-89f3-8e79f5a33524`::finished: {'truesize': '26843545600', 'apparentsize': '26843545600'}
periodic/1::DEBUG::2016-06-27 11:20:18,137::task::595::Storage.TaskManager.Task::(_updateState) Task=`66f32d63-2383-4fc6-89f3-8e79f5a33524`::moving from state preparing -> state finished
periodic/1::DEBUG::2016-06-27 11:20:18,137::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
periodic/1::DEBUG::2016-06-27 11:20:18,137::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
periodic/1::DEBUG::2016-06-27 11:20:18,138::task::993::Storage.TaskManager.Task::(_decref) Task=`66f32d63-2383-4fc6-89f3-8e79f5a33524`::ref 0 aborting False
periodic/3::DEBUG::2016-06-27 11:20:18,138::task::595::Storage.TaskManager.Task::(_updateState) Task=`b3c76eba-3e23-4fd2-8269-3493fbec6768`::moving from state init -> state preparing
periodic/3::INFO::2016-06-27 11:20:18,138::logUtils::48::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID=u'2fec15c6-8f63-4a8b-ad94-00ddb9db625e', spUUID=u'91958960-de08-4eb5-b8ab-92ba066dfda0', imgUUID=u'af5eb920-b180-4b62-88c2-286c60e3286f', volUUID=u'190ab023-fda8-4606-bbc2-d9110f74bc5e', options=None)
periodic/3::INFO::2016-06-27 11:20:18,138::logUtils::51::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '26843545600', 'apparentsize': '26843545600'}
periodic/3::DEBUG::2016-06-27 11:20:18,139::task::1191::Storage.TaskManager.Task::(prepare) Task=`b3c76eba-3e23-4fd2-8269-3493fbec6768`::finished: {'truesize': '26843545600', 'apparentsize': '26843545600'}
periodic/3::DEBUG::2016-06-27 11:20:18,139::task::595::Storage.TaskManager.Task::(_updateState) Task=`b3c76eba-3e23-4fd2-8269-3493fbec6768`::moving from state preparing -> state finished
periodic/3::DEBUG::2016-06-27 11:20:18,139::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
periodic/3::DEBUG::2016-06-27 11:20:18,139::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
periodic/3::DEBUG::2016-06-27 11:20:18,139::task::993::Storage.TaskManager.Task::(_decref) Task=`b3c76eba-3e23-4fd2-8269-3493fbec6768`::ref 0 aborting False
periodic/0::DEBUG::2016-06-27 11:20:18,139::task::595::Storage.TaskManager.Task::(_updateState) Task=`8c82d212-66ce-47ab-bd6c-70c247f9821d`::moving from state init -> state preparing
periodic/0::INFO::2016-06-27 11:20:18,139::logUtils::48::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID=u'2fec15c6-8f63-4a8b-ad94-00ddb9db625e', spUUID=u'91958960-de08-4eb5-b8ab-92ba066dfda0', imgUUID=u'22648231-5420-4f7f-a81b-d57f7b98da77', volUUID=u'3c492e23-5cf9-4d13-89c5-74268076f234', options=None)
periodic/0::INFO::2016-06-27 11:20:18,140::logUtils::51::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '26843545600', 'apparentsize': '26843545600'}
periodic/0::DEBUG::2016-06-27 11:20:18,140::task::1191::Storage.TaskManager.Task::(prepare) Task=`8c82d212-66ce-47ab-bd6c-70c247f9821d`::finished: {'truesize': '26843545600', 'apparentsize': '26843545600'}
periodic/0::DEBUG::2016-06-27 11:20:18,140::task::595::Storage.TaskManager.Task::(_updateState) Task=`8c82d212-66ce-47ab-bd6c-70c247f9821d`::moving from state preparing -> state finished
periodic/0::DEBUG::2016-06-27 11:20:18,140::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
periodic/0::DEBUG::2016-06-27 11:20:18,140::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
periodic/0::DEBUG::2016-06-27 11:20:18,140::task::993::Storage.TaskManager.Task::(_decref) Task=`8c82d212-66ce-47ab-bd6c-70c247f9821d`::ref 0 aborting False
mailbox.SPMMonitor::DEBUG::2016-06-27 11:20:18,227::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) /usr/bin/taskset --cpu-list 0-31 dd if=/rhev/data-center/91958960-de08-4eb5-b8ab-92ba066dfda0/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000 (cwd None)
mailbox.SPMMonitor::DEBUG::2016-06-27 11:20:18,250::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.012117 s, 84.5 MB/s\n'; <rc> = 0
Thread-1124::DEBUG::2016-06-27 11:20:18,442::blockSD::422::Storage.Misc.excCmd::(getReadDelay) /usr/bin/taskset --cpu-list 0-31 /usr/bin/dd if=/dev/2fec15c6-8f63-4a8b-ad94-00ddb9db625e/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-1124::DEBUG::2016-06-27 11:20:18,453::blockSD::422::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000698865 s, 5.9 MB/s\n'; <rc> = 0
mailbox.SPMMonitor::DEBUG::2016-06-27 11:20:20,260::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) /usr/bin/taskset --cpu-list 0-31 dd if=/rhev/data-center/91958960-de08-4eb5-b8ab-92ba066dfda0/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000 (cwd None)
mailbox.SPMMonitor::DEBUG::2016-06-27 11:20:20,284::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.012796 s, 80.0 MB/s\n'; <rc> = 0
mailbox.SPMMonitor::DEBUG::2016-06-27 11:20:22,294::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) /usr/bin/taskset --cpu-list 0-31 dd if=/rhev/data-center/91958960-de08-4eb5-b8ab-92ba066dfda0/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000 (cwd None)
mailbox.SPMMonitor::DEBUG::2016-06-27 11:20:22,318::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0127621 s, 80.2 MB/s\n'; <rc> = 0
mailbox.SPMMonitor::DEBUG::2016-06-27 11:20:24,329::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) /usr/bin/taskset --cpu-list 0-31 dd if=/rhev/data-center/91958960-de08-4eb5-b8ab-92ba066dfda0/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000 (cwd None)
mailbox.SPMMonitor::DEBUG::2016-06-27 11:20:24,351::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0125782 s, 81.4 MB/s\n'; <rc> = 0
jsonrpc.Executor/4::DEBUG::2016-06-27 11:20:26,026::task::595::Storage.TaskManager.Task::(_updateState) Task=`4580db6c-9566-41b5-84bd-699764f67070`::moving from state init -> state preparing
jsonrpc.Executor/4::INFO::2016-06-27 11:20:26,026::logUtils::48::dispatcher::(wrapper) Run and protect: repoStats(options=None)
jsonrpc.Executor/4::INFO::2016-06-27 11:20:26,026::logUtils::51::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'2fec15c6-8f63-4a8b-ad94-00ddb9db625e': {'code': 0, 'actual': True, 'version': 3, 'acquired': True, 'delay': '0.000698865', 'lastCheck': '7.6', 'valid': True}}
jsonrpc.Executor/4::DEBUG::2016-06-27 11:20:26,027::task::1191::Storage.TaskManager.Task::(prepare) Task=`4580db6c-9566-41b5-84bd-699764f67070`::finished: {u'2fec15c6-8f63-4a8b-ad94-00ddb9db625e': {'code': 0, 'actual': True, 'version': 3, 'acquired': True, 'delay': '0.000698865', 'lastCheck': '7.6', 'valid': True}}
jsonrpc.Executor/4::DEBUG::2016-06-27 11:20:26,027::task::595::Storage.TaskManager.Task::(_updateState) Task=`4580db6c-9566-41b5-84bd-699764f67070`::moving from state preparing -> state finished
jsonrpc.Executor/4::DEBUG::2016-06-27 11:20:26,027::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
jsonrpc.Executor/4::DEBUG::2016-06-27 11:20:26,027::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
jsonrpc.Executor/4::DEBUG::2016-06-27 11:20:26,027::task::993::Storage.TaskManager.Task::(_decref) Task=`4580db6c-9566-41b5-84bd-699764f67070`::ref 0 aborting False
mailbox.SPMMonitor::DEBUG::2016-06-27 11:20:26,361::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) /usr/bin/taskset --cpu-list 0-31 dd if=/rhev/data-center/91958960-de08-4eb5-b8ab-92ba066dfda0/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000 (cwd None)
mailbox.SPMMonitor::DEBUG::2016-06-27 11:20:26,385::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0127145 s, 80.5 MB/s\n'; <rc> = 0
jsonrpc.Executor/5::DEBUG::2016-06-27 11:20:27,616::__init__::503::jsonrpc.JsonRpcServer::(_serveRequest) Calling 'StoragePool.getSpmStatus' in bridge with {u'storagepoolID': u'91958960-de08-4eb5-b8ab-92ba066dfda0'}
jsonrpc.Executor/5::DEBUG::2016-06-27 11:20:27,617::task::595::Storage.TaskManager.Task::(_updateState) Task=`dd1c0ee9-1234-4c9c-b385-63d920afb4b8`::moving from state init -> state preparing
jsonrpc.Executor/5::INFO::2016-06-27 11:20:27,617::logUtils::48::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID=u'91958960-de08-4eb5-b8ab-92ba066dfda0', options=None)
jsonrpc.Executor/5::INFO::2016-06-27 11:20:27,631::logUtils::51::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 3, 'spmStatus': 'SPM', 'spmLver': 935L}}
jsonrpc.Executor/5::DEBUG::2016-06-27 11:20:27,631::task::1191::Storage.TaskManager.Task::(prepare) Task=`dd1c0ee9-1234-4c9c-b385-63d920afb4b8`::finished: {'spm_st': {'spmId': 3, 'spmStatus': 'SPM', 'spmLver': 935L}}
jsonrpc.Executor/5::DEBUG::2016-06-27 11:20:27,632::task::595::Storage.TaskManager.Task::(_updateState) Task=`dd1c0ee9-1234-4c9c-b385-63d920afb4b8`::moving from state preparing -> state finished
jsonrpc.Executor/5::DEBUG::2016-06-27 11:20:27,632::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
jsonrpc.Executor/5::DEBUG::2016-06-27 11:20:27,632::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
jsonrpc.Executor/5::DEBUG::2016-06-27 11:20:27,632::task::993::Storage.TaskManager.Task::(_decref) Task=`dd1c0ee9-1234-4c9c-b385-63d920afb4b8`::ref 0 aborting False
jsonrpc.Executor/5::DEBUG::2016-06-27 11:20:27,632::__init__::533::jsonrpc.JsonRpcServer::(_serveRequest) Return 'StoragePool.getSpmStatus' in bridge with {'spmId': 3, 'spmStatus': 'SPM', 'spmLver': 935L}
mailbox.SPMMonitor::DEBUG::2016-06-27 11:20:28,399::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) /usr/bin/taskset --cpu-list 0-31 dd if=/rhev/data-center/91958960-de08-4eb5-b8ab-92ba066dfda0/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000 (cwd None)
mailbox.SPMMonitor::DEBUG::2016-06-27 11:20:28,424::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0125835 s, 81.4 MB/s\n'; <rc> = 0
Thread-1124::DEBUG::2016-06-27 11:20:28,457::blockSD::422::Storage.Misc.excCmd::(getReadDelay) /usr/bin/taskset --cpu-list 0-31 /usr/bin/dd if=/dev/2fec15c6-8f63-4a8b-ad94-00ddb9db625e/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-1124::DEBUG::2016-06-27 11:20:28,468::blockSD::422::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000676704 s, 6.1 MB/s\n'; <rc> = 0
jsonrpc.Executor/3::DEBUG::2016-06-27 11:20:28,640::__init__::503::jsonrpc.JsonRpcServer::(_serveRequest) Calling 'StoragePool.getInfo' in bridge with {u'storagepoolID': u'91958960-de08-4eb5-b8ab-92ba066dfda0'}
jsonrpc.Executor/3::DEBUG::2016-06-27 11:20:28,641::task::595::Storage.TaskManager.Task::(_updateState) Task=`cba37e23-ebc5-4eb9-a4f1-54e59cc91403`::moving from state init -> state preparing
jsonrpc.Executor/3::INFO::2016-06-27 11:20:28,641::logUtils::48::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID=u'91958960-de08-4eb5-b8ab-92ba066dfda0', options=None)
jsonrpc.Executor/3::DEBUG::2016-06-27 11:20:28,641::resourceManager::199::Storage.ResourceManager.Request::(__init__) ResName=`Storage.91958960-de08-4eb5-b8ab-92ba066dfda0`ReqID=`f47f7305-2984-4cd7-bace-92a0af2187ef`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2642' at 'getStoragePoolInfo'
jsonrpc.Executor/3::DEBUG::2016-06-27 11:20:28,642::resourceManager::545::Storage.ResourceManager::(registerResource) Trying to register resource 'Storage.91958960-de08-4eb5-b8ab-92ba066dfda0' for lock type 'shared'
jsonrpc.Executor/3::DEBUG::2016-06-27 11:20:28,642::resourceManager::604::Storage.ResourceManager::(registerResource) Resource 'Storage.91958960-de08-4eb5-b8ab-92ba066dfda0' is free. Now locking as 'shared' (1 active user)
jsonrpc.Executor/3::DEBUG::2016-06-27 11:20:28,642::resourceManager::239::Storage.ResourceManager.Request::(grant) ResName=`Storage.91958960-de08-4eb5-b8ab-92ba066dfda0`ReqID=`f47f7305-2984-4cd7-bace-92a0af2187ef`::Granted request
jsonrpc.Executor/3::DEBUG::2016-06-27 11:20:28,642::task::827::Storage.TaskManager.Task::(resourceAcquired) Task=`cba37e23-ebc5-4eb9-a4f1-54e59cc91403`::_resourcesAcquired: Storage.91958960-de08-4eb5-b8ab-92ba066dfda0 (shared)
jsonrpc.Executor/3::DEBUG::2016-06-27 11:20:28,642::task::993::Storage.TaskManager.Task::(_decref) Task=`cba37e23-ebc5-4eb9-a4f1-54e59cc91403`::ref 1 aborting False
jsonrpc.Executor/3::INFO::2016-06-27 11:20:28,654::logUtils::51::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'No Description', 'isoprefix': '', 'pool_status': 'connected', 'lver': 935L, 'domains': u'2fec15c6-8f63-4a8b-ad94-00ddb9db625e:Active', 'master_uuid': '2fec15c6-8f63-4a8b-ad94-00ddb9db625e', 'version': '3', 'spm_id': 3, 'type': 'ISCSI', 'master_ver': 2}, 'dominfo': {u'2fec15c6-8f63-4a8b-ad94-00ddb9db625e': {'status': u'Active', 'diskfree': '1864552677376', 'isoprefix': '', 'alerts': [], 'disktotal': '2198620602368', 'version': 3}}}
jsonrpc.Executor/3::DEBUG::2016-06-27 11:20:28,654::task::1191::Storage.TaskManager.Task::(prepare) Task=`cba37e23-ebc5-4eb9-a4f1-54e59cc91403`::finished: {'info': {'name': 'No Description', 'isoprefix': '', 'pool_status': 'connected', 'lver': 935L, 'domains': u'2fec15c6-8f63-4a8b-ad94-00ddb9db625e:Active', 'master_uuid': '2fec15c6-8f63-4a8b-ad94-00ddb9db625e', 'version': '3', 'spm_id': 3, 'type': 'ISCSI', 'master_ver': 2}, 'dominfo': {u'2fec15c6-8f63-4a8b-ad94-00ddb9db625e': {'status': u'Active', 'diskfree': '1864552677376', 'isoprefix': '', 'alerts': [], 'disktotal': '2198620602368', 'version': 3}}}
jsonrpc.Executor/3::DEBUG::2016-06-27 11:20:28,654::task::595::Storage.TaskManager.Task::(_updateState) Task=`cba37e23-ebc5-4eb9-a4f1-54e59cc91403`::moving from state preparing -> state finished
jsonrpc.Executor/3::DEBUG::2016-06-27 11:20:28,654::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {u'Storage.91958960-de08-4eb5-b8ab-92ba066dfda0': < ResourceRef 'Storage.91958960-de08-4eb5-b8ab-92ba066dfda0', isValid: 'True' obj: 'None'>}
jsonrpc.Executor/3::DEBUG::2016-06-27 11:20:28,654::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
jsonrpc.Executor/3::DEBUG::2016-06-27 11:20:28,655::resourceManager::619::Storage.ResourceManager::(releaseResource) Trying to release resource 'Storage.91958960-de08-4eb5-b8ab-92ba066dfda0'
jsonrpc.Executor/3::DEBUG::2016-06-27 11:20:28,655::resourceManager::638::Storage.ResourceManager::(releaseResource) Released resource 'Storage.91958960-de08-4eb5-b8ab-92ba066dfda0' (0 active users)
jsonrpc.Executor/3::DEBUG::2016-06-27 11:20:28,655::resourceManager::644::Storage.ResourceManager::(releaseResource) Resource 'Storage.91958960-de08-4eb5-b8ab-92ba066dfda0' is free, finding out if anyone is waiting for it.
jsonrpc.Executor/3::DEBUG::2016-06-27 11:20:28,655::resourceManager::652::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'Storage.91958960-de08-4eb5-b8ab-92ba066dfda0', Clearing records.
jsonrpc.Executor/3::DEBUG::2016-06-27 11:20:28,655::task::993::Storage.TaskManager.Task::(_decref) Task=`cba37e23-ebc5-4eb9-a4f1-54e59cc91403`::ref 0 aborting False
jsonrpc.Executor/3::DEBUG::2016-06-27 11:20:28,655::__init__::533::jsonrpc.JsonRpcServer::(_serveRequest) Return 'StoragePool.getInfo' in bridge with {'info': {'name': 'No Description', 'isoprefix': '', 'pool_status': 'connected', 'lver': 935L, 'domains': u'2fec15c6-8f63-4a8b-ad94-00ddb9db625e:Active', 'master_uuid': '2fec15c6-8f63-4a8b-ad94-00ddb9db625e', 'version': '3', 'spm_id': 3, 'type': 'ISCSI', 'master_ver': 2}, 'dominfo': {u'2fec15c6-8f63-4a8b-ad94-00ddb9db625e': {'status': u'Active', 'diskfree': '1864552677376', 'isoprefix': '', 'alerts': [], 'disktotal': '2198620602368', 'version': 3}}}
VM Channels Listener::DEBUG::2016-06-27 11:20:28,853::vmchannels::113::vds::(_handle_timeouts) Timeout on fileno 36.
Reactor thread::INFO::2016-06-27 11:20:29,047::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:53691
Reactor thread::DEBUG::2016-06-27 11:20:29,052::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11
Reactor thread::INFO::2016-06-27 11:20:29,052::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:53691
Reactor thread::DEBUG::2016-06-27 11:20:29,052::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 53691)
BindingXMLRPC::INFO::2016-06-27 11:20:29,052::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:53691
Thread-18104::INFO::2016-06-27 11:20:29,053::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:53691 started
Thread-18104::INFO::2016-06-27 11:20:29,063::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:53691 stopped