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
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_______________________________________________
Users mailing list
Users@ovirt.org
http://lists.ovirt.org/mailman/listinfo/users
