[ovirt-users] VMs halt on Storage Error
David Gerner
davegerner1975 at gmail.com
Mon Jun 27 15:32:37 UTC 2016
Hi,
I'm running into a strange issue that I've been trying to solve
unsuccessfully for a few days now, and I was hoping someone could offer
some insight.
A few days ago I needed to reboot the the server that hosts the management
engine and is also a node in the system. Following proper procedure I
selected a new host to be the SPM, migrated VMs off the Host, and put it
into maintenance mode. After the host came back up (and the management
engine was back online) I noticed that one of my VMs had halted on a
storage error, to rule out the SPM being the issue I asked oVirt to select
a new SPM and it was stuck in a contending loop where each host tries to
contend for SPM status but ultimately fails (every other VM also halted by
this point). The error was "BlockSD master file system FSCK error", after
researching the error I found a post on this list that was the same error
and the author said that a simple FSCK on the offending file system fixed
his issue. I had to force shutdown every VM from the halted state and put
all but one host into maintenance mode. On that host I ran a FSCK on the
offending volume which found a lot of short read errors which it fixed and
afterwards the contending loop was broke and hosts could now successfully
be an SPM.
Now every VM halts on start or resume, even ones that were offline at the
time of the earlier incident, with a Storage Error "abnormal vm stop device
virtio-disk0 error eio". I can't even create new disks because it fails
with an error. I've attached what I think is the relevant VDSM log portion
of a VM trying to resume, if more is needed please just let me know.
I'm worried FSCK and I mangled the file system, and have no idea how to
repair it.
Any insight is greatly appreciated.
Thank you,
Dave
oVirt Engine Version: 3.6.2.6-1.el7.centos
Storage Tech: iSCSI
4 Servers each with:
OS: RHEL - 7 - 2.1511.el7.centos.2.10
Kernel: 3.10.0 - 327.4.5.el7.x86_64
KVM Version: 2.3.0 - 31.el7_2.7.1
libVirt Version: libvirt-1.2.17-13.el7_2.5
VDSM Version: vdsm-4.17.28-0.el7.centos
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.ovirt.org/pipermail/users/attachments/20160627/73ccf57a/attachment-0001.html>
-------------- next part --------------
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
More information about the Users
mailing list