Attachment 936544 Details for Bug 1109880 – extract of vdsm log

extract of vdsm log

extract_vdsm.log (text/plain), 26.76 KB, created by exploit on 2014-09-11 13:20:27 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: exploit

Created: 2014-09-11 13:20:27 UTC

Size: 26.76 KB

patch

obsolete

>Thread-13::DEBUG::2014-09-11 14:39:05,387::BindingXMLRPC::1067::vds::(wrapper) client [10.34.30.46]::call vmCreate with ({'acpiEnable': 'true', 'emulatedMachine': 'rhel6.5.0', 'vmId': '5974b4fc-d37d-49a1-a102-6ab68775ce07', 'memGuaranteedSize': 682, 'spiceSslCipherSuite': 'DEFAULT', 'timeOffset': '0', 'cpuType': 'Westmere', 'smp': '1', 'custom': {}, 'vmType': 'kvm', 'memSize': 1024, 'smpCoresPerSocket': '1', 'vmName': 'testcentos7gui', 'nice': '0', 'smartcardEnable': 'false', 'keyboardLayout': 'en-us', 'kvmEnable': 'true', 'transparentHugePages': 'true', 'devices': [{'device': 'qxl', 'specParams': {'vram': '32768', 'heads': '1'}, 'type': 'video', 'deviceId': 'c356c443-83e1-4a95-b3c4-743035fa075a'}, {'index': '2', 'iface': 'ide', 'specParams': {'path': 'CentOS-7.0-1406-x86_64-DVD.iso'}, 'readonly': 'true', 'deviceId': '61dd30c1-aba1-4769-8fee-9e42d1a6a9c9', 'path': '/rhev/data-center/mnt/hupe.abes.fr:_ovirt__iso/cdc09bbb-fd7a-4a48-8b6a-cd7bccbecc3d/images/11111111-1111-1111-1111-111111111111/CentOS-7.0-1406-x86_64-DVD.iso', 'device': 'cdrom', 'shared': 'false', 'type': 'disk'}, {'index': '2', 'iface': 'ide', 'specParams': {'path': 'CentOS-7.0-1406-x86_64-DVD.iso'}, 'readonly': 'true', 'deviceId': '65b847e4-74ec-409c-b927-85f2447f3650', 'path': '/rhev/data-center/mnt/hupe.abes.fr:_ovirt__iso/cdc09bbb-fd7a-4a48-8b6a-cd7bccbecc3d/images/11111111-1111-1111-1111-111111111111/CentOS-7.0-1406-x86_64-DVD.iso', 'device': 'cdrom', 'shared': 'false', 'type': 'disk'}, {'index': 0, 'iface': 'virtio', 'format': 'raw', 'type': 'disk', 'volumeID': '119bed1b-3b2e-4790-ae75-7eed3d5e386c', 'imageID': 'b24d1090-4c9b-4f74-9be9-a9f1950c201b', 'specParams': {}, 'readonly': 'false', 'domainID': '5ef8572c-0ab5-4491-994a-e4c30230a525', 'deviceId': 'b24d1090-4c9b-4f74-9be9-a9f1950c201b', 'poolID': '48ca3019-9dbf-4ef3-98e9-08105d396350', 'device': 'disk', 'shared': 'false', 'propagateErrors': 'off', 'optional': 'false'}, {'nicModel': 'pv', 'macAddr': '00:1a:4a:22:1e:59', 'linkActive': 'true', 'network': 'brv11', 'filter': 'vdsm-no-mac-spoofing', 'specParams': {'inbound': {}, 'outbound': {}}, 'deviceId': '0d12b244-baff-4bad-8f7d-7e8b184e20a5', 'device': 'bridge', 'type': 'interface'}, {'device': 'memballoon', 'specParams': {'model': 'virtio'}, 'type': 'balloon', 'deviceId': '5ef09f26-7058-4b30-93ce-1468479524b0'}, {'index': '0', 'specParams': {}, 'deviceId': '5a93e191-f4b7-475a-98a3-e42d046dfbe1', 'device': 'scsi', 'model': 'virtio-scsi', 'type': 'controller'}], 'maxVCpus': '160', 'spiceSecureChannels': 'smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard', 'display': 'qxl'},) {} flowID [5953ebf8]
>Thread-13::INFO::2014-09-11 14:39:05,404::API::667::vds::(_getNetworkIp) network None: using 0
>Thread-13::INFO::2014-09-11 14:39:05,404::clientIF::364::vds::(createVm) vmContainerLock acquired by vm 5974b4fc-d37d-49a1-a102-6ab68775ce07
>Thread-5159::DEBUG::2014-09-11 14:39:05,411::vm::2270::vm.Vm::(_startUnderlyingVm) vmId=`5974b4fc-d37d-49a1-a102-6ab68775ce07`::Start
>Thread-13::DEBUG::2014-09-11 14:39:05,411::clientIF::377::vds::(createVm) Total desktops after creation of 5974b4fc-d37d-49a1-a102-6ab68775ce07 is 3
>Thread-5159::DEBUG::2014-09-11 14:39:05,414::vm::2274::vm.Vm::(_startUnderlyingVm) vmId=`5974b4fc-d37d-49a1-a102-6ab68775ce07`::_ongoingCreations acquired
>Thread-13::DEBUG::2014-09-11 14:39:05,414::BindingXMLRPC::1074::vds::(wrapper) return vmCreate with {'status': {'message': 'Done', 'code': 0}, 'vmList': {'status': 'WaitForLaunch', 'acpiEnable': 'true', 'emulatedMachine': 'rhel6.5.0', 'vmId': '5974b4fc-d37d-49a1-a102-6ab68775ce07', 'pid': '0', 'memGuaranteedSize': 682, 'timeOffset': '0', 'keyboardLayout': 'en-us', 'displayPort': '-1', 'displaySecurePort': '-1', 'spiceSslCipherSuite': 'DEFAULT', 'cpuType': 'Westmere', 'custom': {}, 'clientIp': '', 'nicModel': 'rtl8139,pv', 'smartcardEnable': 'false', 'kvmEnable': 'true', 'transparentHugePages': 'true', 'devices': [{'device': 'qxl', 'specParams': {'vram': '32768', 'heads': '1'}, 'type': 'video', 'deviceId': 'c356c443-83e1-4a95-b3c4-743035fa075a'}, {'index': '2', 'iface': 'ide', 'specParams': {'path': 'CentOS-7.0-1406-x86_64-DVD.iso'}, 'readonly': 'true', 'deviceId': '61dd30c1-aba1-4769-8fee-9e42d1a6a9c9', 'path': '/rhev/data-center/mnt/hupe.abes.fr:_ovirt__iso/cdc09bbb-fd7a-4a48-8b6a-cd7bccbecc3d/images/11111111-1111-1111-1111-111111111111/CentOS-7.0-1406-x86_64-DVD.iso', 'device': 'cdrom', 'shared': 'false', 'type': 'disk'}, {'index': '2', 'iface': 'ide', 'specParams': {'path': 'CentOS-7.0-1406-x86_64-DVD.iso'}, 'readonly': 'true', 'deviceId': '65b847e4-74ec-409c-b927-85f2447f3650', 'path': '/rhev/data-center/mnt/hupe.abes.fr:_ovirt__iso/cdc09bbb-fd7a-4a48-8b6a-cd7bccbecc3d/images/11111111-1111-1111-1111-111111111111/CentOS-7.0-1406-x86_64-DVD.iso', 'device': 'cdrom', 'shared': 'false', 'type': 'disk'}, {'index': 0, 'iface': 'virtio', 'format': 'raw', 'type': 'disk', 'volumeID': '119bed1b-3b2e-4790-ae75-7eed3d5e386c', 'imageID': 'b24d1090-4c9b-4f74-9be9-a9f1950c201b', 'specParams': {}, 'readonly': 'false', 'domainID': '5ef8572c-0ab5-4491-994a-e4c30230a525', 'deviceId': 'b24d1090-4c9b-4f74-9be9-a9f1950c201b', 'poolID': '48ca3019-9dbf-4ef3-98e9-08105d396350', 'device': 'disk', 'shared': 'false', 'propagateErrors': 'off', 'optional': 'false'}, {'nicModel': 'pv', 'macAddr': '00:1a:4a:22:1e:59', 'linkActive': 'true', 'network': 'brv11', 'filter': 'vdsm-no-mac-spoofing', 'specParams': {'inbound': {}, 'outbound': {}}, 'deviceId': '0d12b244-baff-4bad-8f7d-7e8b184e20a5', 'device': 'bridge', 'type': 'interface'}, {'device': 'memballoon', 'specParams': {'model': 'virtio'}, 'type': 'balloon', 'deviceId': '5ef09f26-7058-4b30-93ce-1468479524b0'}, {'index': '0', 'specParams': {}, 'deviceId': '5a93e191-f4b7-475a-98a3-e42d046dfbe1', 'device': 'scsi', 'model': 'virtio-scsi', 'type': 'controller'}], 'smp': '1', 'vmType': 'kvm', 'memSize': 1024, 'displayIp': '0', 'maxVCpus': '160', 'spiceSecureChannels': 'smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard', 'smpCoresPerSocket': '1', 'vmName': 'testcentos7gui', 'display': 'qxl', 'nice': '0'}}
>Thread-5159::INFO::2014-09-11 14:39:05,417::vm::3151::vm.Vm::(_run) vmId=`5974b4fc-d37d-49a1-a102-6ab68775ce07`::VM wrapper has started
>Thread-5159::DEBUG::2014-09-11 14:39:05,424::task::595::TaskManager.Task::(_updateState) Task=`b10f7d3a-5350-4c40-8208-9dc5d83d7f0c`::moving from state init -> state preparing
>Thread-5159::INFO::2014-09-11 14:39:05,428::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='5ef8572c-0ab5-4491-994a-e4c30230a525', spUUID='48ca3019-9dbf-4ef3-98e9-08105d396350', imgUUID='b24d1090-4c9b-4f74-9be9-a9f1950c201b', volUUID='119bed1b-3b2e-4790-ae75-7eed3d5e386c', options=None)
>Thread-5159::DEBUG::2014-09-11 14:39:05,433::lvm::427::OperationMutex::(_reloadlvs) Operation 'lvm reload operation' got the operation mutex
>Thread-5159::DEBUG::2014-09-11 14:39:05,440::lvm::296::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm lvs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/360060160a6212b007e927c973bd4e211|\', \'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 | -o uuid,name,vg_name,attr,size,seg_start_pe,devices,tags 5ef8572c-0ab5-4491-994a-e4c30230a525' (cwd None)
>Thread-14::DEBUG::2014-09-11 14:39:05,489::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/bin/dd if=/rhev/data-center/mnt/hupe.abes.fr:_ovirt__export/52ba230a-bfb3-4add-b404-da67cc61f47a/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1' (cwd None)
>Thread-14::DEBUG::2014-09-11 14:39:05,505::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n351 bytes (351 B) copied, 0.000583944 s, 601 kB/s\n'; <rc> = 0
>Thread-19::DEBUG::2014-09-11 14:39:05,709::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/bin/dd if=/rhev/data-center/mnt/hupe.abes.fr:_ovirt__iso/cdc09bbb-fd7a-4a48-8b6a-cd7bccbecc3d/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1' (cwd None)
>Thread-19::DEBUG::2014-09-11 14:39:05,723::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n379 bytes (379 B) copied, 0.000513745 s, 738 kB/s\n'; <rc> = 0
>Thread-5159::DEBUG::2014-09-11 14:39:05,760::lvm::296::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-5159::DEBUG::2014-09-11 14:39:06,025::lvm::462::Storage.LVM::(_reloadlvs) lvs reloaded
>Thread-5159::DEBUG::2014-09-11 14:39:06,025::lvm::462::OperationMutex::(_reloadlvs) Operation 'lvm reload operation' released the operation mutex
>Thread-5159::INFO::2014-09-11 14:39:06,026::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '21474836480', 'apparentsize': '21474836480'}
>Thread-5159::DEBUG::2014-09-11 14:39:06,026::task::1185::TaskManager.Task::(prepare) Task=`b10f7d3a-5350-4c40-8208-9dc5d83d7f0c`::finished: {'truesize': '21474836480', 'apparentsize': '21474836480'}
>Thread-5159::DEBUG::2014-09-11 14:39:06,027::task::595::TaskManager.Task::(_updateState) Task=`b10f7d3a-5350-4c40-8208-9dc5d83d7f0c`::moving from state preparing -> state finished
>Thread-5159::DEBUG::2014-09-11 14:39:06,027::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-5159::DEBUG::2014-09-11 14:39:06,027::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-5159::DEBUG::2014-09-11 14:39:06,028::task::990::TaskManager.Task::(_decref) Task=`b10f7d3a-5350-4c40-8208-9dc5d83d7f0c`::ref 0 aborting False
>Thread-5159::INFO::2014-09-11 14:39:06,028::clientIF::322::vds::(prepareVolumePath) prepared volume path: /rhev/data-center/mnt/hupe.abes.fr:_ovirt__iso/cdc09bbb-fd7a-4a48-8b6a-cd7bccbecc3d/images/11111111-1111-1111-1111-111111111111/CentOS-7.0-1406-x86_64-DVD.iso
>Thread-5159::INFO::2014-09-11 14:39:06,028::clientIF::322::vds::(prepareVolumePath) prepared volume path: /rhev/data-center/mnt/hupe.abes.fr:_ovirt__iso/cdc09bbb-fd7a-4a48-8b6a-cd7bccbecc3d/images/11111111-1111-1111-1111-111111111111/CentOS-7.0-1406-x86_64-DVD.iso
>Thread-5159::DEBUG::2014-09-11 14:39:06,029::task::595::TaskManager.Task::(_updateState) Task=`2bd8f3f3-b73c-43d6-836d-ccd0451d0a7a`::moving from state init -> state preparing
>Thread-5159::INFO::2014-09-11 14:39:06,030::logUtils::44::dispatcher::(wrapper) Run and protect: prepareImage(sdUUID='5ef8572c-0ab5-4491-994a-e4c30230a525', spUUID='48ca3019-9dbf-4ef3-98e9-08105d396350', imgUUID='b24d1090-4c9b-4f74-9be9-a9f1950c201b', leafUUID='119bed1b-3b2e-4790-ae75-7eed3d5e386c')
>Thread-5159::DEBUG::2014-09-11 14:39:06,031::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.5ef8572c-0ab5-4491-994a-e4c30230a525`ReqID=`b27195d5-6270-4e53-91ab-fa56e867b616`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3248' at 'prepareImage'
>Thread-5159::DEBUG::2014-09-11 14:39:06,031::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.5ef8572c-0ab5-4491-994a-e4c30230a525' for lock type 'shared'
>Thread-5159::DEBUG::2014-09-11 14:39:06,031::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.5ef8572c-0ab5-4491-994a-e4c30230a525' is free. Now locking as 'shared' (1 active user)
>Thread-5159::DEBUG::2014-09-11 14:39:06,032::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.5ef8572c-0ab5-4491-994a-e4c30230a525`ReqID=`b27195d5-6270-4e53-91ab-fa56e867b616`::Granted request
>Thread-5159::DEBUG::2014-09-11 14:39:06,032::task::827::TaskManager.Task::(resourceAcquired) Task=`2bd8f3f3-b73c-43d6-836d-ccd0451d0a7a`::_resourcesAcquired: Storage.5ef8572c-0ab5-4491-994a-e4c30230a525 (shared)
>Thread-5159::DEBUG::2014-09-11 14:39:06,033::task::990::TaskManager.Task::(_decref) Task=`2bd8f3f3-b73c-43d6-836d-ccd0451d0a7a`::ref 1 aborting False
>Thread-5159::DEBUG::2014-09-11 14:39:06,033::lvm::427::OperationMutex::(_reloadlvs) Operation 'lvm reload operation' got the operation mutex
>Thread-5159::DEBUG::2014-09-11 14:39:06,034::lvm::296::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm lvs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/360060160a6212b007e927c973bd4e211|\', \'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 | -o uuid,name,vg_name,attr,size,seg_start_pe,devices,tags 5ef8572c-0ab5-4491-994a-e4c30230a525' (cwd None)
>Thread-24::DEBUG::2014-09-11 14:39:06,342::blockSD::600::Storage.Misc.excCmd::(getReadDelay) '/bin/dd if=/dev/5ef8572c-0ab5-4491-994a-e4c30230a525/metadata iflag=direct of=/dev/null bs=4096 count=1' (cwd None)
>Thread-24::DEBUG::2014-09-11 14:39:06,372::blockSD::600::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000387163 s, 10.6 MB/s\n'; <rc> = 0
>Thread-5159::DEBUG::2014-09-11 14:39:06,432::lvm::296::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-5159::DEBUG::2014-09-11 14:39:06,700::lvm::462::Storage.LVM::(_reloadlvs) lvs reloaded
>Thread-5159::DEBUG::2014-09-11 14:39:06,700::lvm::462::OperationMutex::(_reloadlvs) Operation 'lvm reload operation' released the operation mutex
>Thread-5159::DEBUG::2014-09-11 14:39:06,705::lvm::296::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm lvchange --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/360060160a6212b007e927c973bd4e211|\', \'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 5ef8572c-0ab5-4491-994a-e4c30230a525/119bed1b-3b2e-4790-ae75-7eed3d5e386c' (cwd None)
>Thread-5159::DEBUG::2014-09-11 14:39:07,240::lvm::296::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-5159::DEBUG::2014-09-11 14:39:07,242::lvm::513::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-5159::DEBUG::2014-09-11 14:39:07,243::lvm::525::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-5159::DEBUG::2014-09-11 14:39:07,249::lvm::427::OperationMutex::(_reloadlvs) Operation 'lvm reload operation' got the operation mutex
>Thread-5159::DEBUG::2014-09-11 14:39:07,250::lvm::296::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm lvs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/360060160a6212b007e927c973bd4e211|\', \'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 | -o uuid,name,vg_name,attr,size,seg_start_pe,devices,tags 5ef8572c-0ab5-4491-994a-e4c30230a525' (cwd None)
>Thread-5159::DEBUG::2014-09-11 14:39:07,578::lvm::296::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-5159::DEBUG::2014-09-11 14:39:07,856::lvm::462::Storage.LVM::(_reloadlvs) lvs reloaded
>Thread-5159::DEBUG::2014-09-11 14:39:07,856::lvm::462::OperationMutex::(_reloadlvs) Operation 'lvm reload operation' released the operation mutex
>Thread-5159::INFO::2014-09-11 14:39:07,857::logUtils::47::dispatcher::(wrapper) Run and protect: prepareImage, Return response: {'info': {'domainID': '5ef8572c-0ab5-4491-994a-e4c30230a525', 'volType': 'path', 'leaseOffset': 221249536, 'path': '/rhev/data-center/mnt/blockSD/5ef8572c-0ab5-4491-994a-e4c30230a525/images/b24d1090-4c9b-4f74-9be9-a9f1950c201b/119bed1b-3b2e-4790-ae75-7eed3d5e386c', 'volumeID': '119bed1b-3b2e-4790-ae75-7eed3d5e386c', 'leasePath': '/dev/5ef8572c-0ab5-4491-994a-e4c30230a525/leases', 'imageID': 'b24d1090-4c9b-4f74-9be9-a9f1950c201b'}, 'path': '/rhev/data-center/mnt/blockSD/5ef8572c-0ab5-4491-994a-e4c30230a525/images/b24d1090-4c9b-4f74-9be9-a9f1950c201b/119bed1b-3b2e-4790-ae75-7eed3d5e386c', 'imgVolumesInfo': [{'domainID': '5ef8572c-0ab5-4491-994a-e4c30230a525', 'volType': 'path', 'leaseOffset': 221249536, 'path': '/rhev/data-center/mnt/blockSD/5ef8572c-0ab5-4491-994a-e4c30230a525/images/b24d1090-4c9b-4f74-9be9-a9f1950c201b/119bed1b-3b2e-4790-ae75-7eed3d5e386c', 'volumeID': '119bed1b-3b2e-4790-ae75-7eed3d5e386c', 'leasePath': '/dev/5ef8572c-0ab5-4491-994a-e4c30230a525/leases', 'imageID': 'b24d1090-4c9b-4f74-9be9-a9f1950c201b'}]}
>Thread-5159::DEBUG::2014-09-11 14:39:07,858::task::1185::TaskManager.Task::(prepare) Task=`2bd8f3f3-b73c-43d6-836d-ccd0451d0a7a`::finished: {'info': {'domainID': '5ef8572c-0ab5-4491-994a-e4c30230a525', 'volType': 'path', 'leaseOffset': 221249536, 'path': '/rhev/data-center/mnt/blockSD/5ef8572c-0ab5-4491-994a-e4c30230a525/images/b24d1090-4c9b-4f74-9be9-a9f1950c201b/119bed1b-3b2e-4790-ae75-7eed3d5e386c', 'volumeID': '119bed1b-3b2e-4790-ae75-7eed3d5e386c', 'leasePath': '/dev/5ef8572c-0ab5-4491-994a-e4c30230a525/leases', 'imageID': 'b24d1090-4c9b-4f74-9be9-a9f1950c201b'}, 'path': '/rhev/data-center/mnt/blockSD/5ef8572c-0ab5-4491-994a-e4c30230a525/images/b24d1090-4c9b-4f74-9be9-a9f1950c201b/119bed1b-3b2e-4790-ae75-7eed3d5e386c', 'imgVolumesInfo': [{'domainID': '5ef8572c-0ab5-4491-994a-e4c30230a525', 'volType': 'path', 'leaseOffset': 221249536, 'path': '/rhev/data-center/mnt/blockSD/5ef8572c-0ab5-4491-994a-e4c30230a525/images/b24d1090-4c9b-4f74-9be9-a9f1950c201b/119bed1b-3b2e-4790-ae75-7eed3d5e386c', 'volumeID': '119bed1b-3b2e-4790-ae75-7eed3d5e386c', 'leasePath': '/dev/5ef8572c-0ab5-4491-994a-e4c30230a525/leases', 'imageID': 'b24d1090-4c9b-4f74-9be9-a9f1950c201b'}]}
>Thread-5159::DEBUG::2014-09-11 14:39:07,858::task::595::TaskManager.Task::(_updateState) Task=`2bd8f3f3-b73c-43d6-836d-ccd0451d0a7a`::moving from state preparing -> state finished
>Thread-5159::DEBUG::2014-09-11 14:39:07,859::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.5ef8572c-0ab5-4491-994a-e4c30230a525': < ResourceRef 'Storage.5ef8572c-0ab5-4491-994a-e4c30230a525', isValid: 'True' obj: 'None'>}
>Thread-5159::DEBUG::2014-09-11 14:39:07,859::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-5159::DEBUG::2014-09-11 14:39:07,860::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.5ef8572c-0ab5-4491-994a-e4c30230a525'
>Thread-5159::DEBUG::2014-09-11 14:39:07,860::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.5ef8572c-0ab5-4491-994a-e4c30230a525' (0 active users)
>Thread-5159::DEBUG::2014-09-11 14:39:07,860::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.5ef8572c-0ab5-4491-994a-e4c30230a525' is free, finding out if anyone is waiting for it.
>Thread-5159::DEBUG::2014-09-11 14:39:07,861::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.5ef8572c-0ab5-4491-994a-e4c30230a525', Clearing records.
>Thread-5159::DEBUG::2014-09-11 14:39:07,861::task::990::TaskManager.Task::(_decref) Task=`2bd8f3f3-b73c-43d6-836d-ccd0451d0a7a`::ref 0 aborting False
>Thread-5159::INFO::2014-09-11 14:39:07,862::clientIF::322::vds::(prepareVolumePath) prepared volume path: /rhev/data-center/mnt/blockSD/5ef8572c-0ab5-4491-994a-e4c30230a525/images/b24d1090-4c9b-4f74-9be9-a9f1950c201b/119bed1b-3b2e-4790-ae75-7eed3d5e386c
>Thread-5159::DEBUG::2014-09-11 14:39:07,892::vm::3190::vm.Vm::(_run) vmId=`5974b4fc-d37d-49a1-a102-6ab68775ce07`::<?xml version="1.0" encoding="utf-8"?>
><domain type="kvm">
>	<name>testcentos7gui</name>
>	<uuid>5974b4fc-d37d-49a1-a102-6ab68775ce07</uuid>
>	<memory>1048576</memory>
>	<currentMemory>1048576</currentMemory>
>	<vcpu current="1">160</vcpu>
>	<memtune>
>		<min_guarantee>698368</min_guarantee>
>	</memtune>
>	<devices>
>		<channel type="unix">
>			<target name="com.redhat.rhevm.vdsm" type="virtio"/>
>			<source mode="bind" path="/var/lib/libvirt/qemu/channels/5974b4fc-d37d-49a1-a102-6ab68775ce07.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/5974b4fc-d37d-49a1-a102-6ab68775ce07.org.qemu.guest_agent.0"/>
>		</channel>
>		<input bus="ps2" type="mouse"/>
>		<channel type="spicevmc">
>			<target name="com.redhat.spice.0" type="virtio"/>
>		</channel>
>		<graphics autoport="yes" keymap="en-us" listen="0" passwd="*****" passwdValidTo="1970-01-01T00:00:01" port="-1" tlsPort="-1" type="spice">
>			<channel mode="secure" name="main"/>
>			<channel mode="secure" name="inputs"/>
>			<channel mode="secure" name="cursor"/>
>			<channel mode="secure" name="playback"/>
>			<channel mode="secure" name="record"/>
>			<channel mode="secure" name="display"/>
>			<channel mode="secure" name="usbredir"/>
>			<channel mode="secure" name="smartcard"/>
>		</graphics>
>		<memballoon model="virtio"/>
>		<controller index="0" model="virtio-scsi" type="scsi"/>
>		<video>
>			<model heads="1" type="qxl" vram="32768"/>
>		</video>
>		<interface type="bridge">
>			<mac address="00:1a:4a:22:1e:59"/>
>			<model type="virtio"/>
>			<source bridge="brv11"/>
>			<filterref filter="vdsm-no-mac-spoofing"/>
>			<link state="up"/>
>			<bandwidth/>
>		</interface>
>		<disk device="cdrom" snapshot="no" type="file">
>			<source file="/rhev/data-center/mnt/hupe.abes.fr:_ovirt__iso/cdc09bbb-fd7a-4a48-8b6a-cd7bccbecc3d/images/11111111-1111-1111-1111-111111111111/CentOS-7.0-1406-x86_64-DVD.iso" startupPolicy="optional"/>
>			<target bus="ide" dev="hdc"/>
>			<readonly/>
>			<serial/>
>		</disk>
>		<disk device="cdrom" snapshot="no" type="file">
>			<source file="/rhev/data-center/mnt/hupe.abes.fr:_ovirt__iso/cdc09bbb-fd7a-4a48-8b6a-cd7bccbecc3d/images/11111111-1111-1111-1111-111111111111/CentOS-7.0-1406-x86_64-DVD.iso" startupPolicy="optional"/>
>			<target bus="ide" dev="hdc"/>
>			<readonly/>
>			<serial/>
>		</disk>
>		<disk device="disk" snapshot="no" type="block">
>			<source dev="/rhev/data-center/mnt/blockSD/5ef8572c-0ab5-4491-994a-e4c30230a525/images/b24d1090-4c9b-4f74-9be9-a9f1950c201b/119bed1b-3b2e-4790-ae75-7eed3d5e386c"/>
>			<target bus="virtio" dev="vda"/>
>			<serial>b24d1090-4c9b-4f74-9be9-a9f1950c201b</serial>
>			<driver cache="none" error_policy="stop" io="native" name="qemu" type="raw"/>
>		</disk>
>	</devices>
>	<os>
>		<type arch="x86_64" machine="rhel6.5.0">hvm</type>
>		<smbios mode="sysinfo"/>
>	</os>
>	<sysinfo type="smbios">
>		<system>
>			<entry name="manufacturer">oVirt</entry>
>			<entry name="product">oVirt Node</entry>
>			<entry name="version">6-5.el6.centos.11.2</entry>
>			<entry name="serial">4C4C4544-0043-5210-8037-B9C04F5A5A31</entry>
>			<entry name="uuid">5974b4fc-d37d-49a1-a102-6ab68775ce07</entry>
>		</system>
>	</sysinfo>
>	<clock adjustment="0" offset="variable">
>		<timer name="rtc" tickpolicy="catchup"/>
>	</clock>
>	<features>
>		<acpi/>
>	</features>
>	<cpu match="exact">
>		<model>Westmere</model>
>		<topology cores="1" sockets="160" threads="1"/>
>	</cpu>
></domain>
>
>Thread-5159::DEBUG::2014-09-11 14:39:09,179::libvirtconnection::124::root::(wrapper) Unknown libvirterror: ecode: 1 edom: 10 level: 2 message: internal error process exited while connecting to monitor: qemu-kvm: -drive file=/rhev/data-center/mnt/hupe.abes.fr:_ovirt__iso/cdc09bbb-fd7a-4a48-8b6a-cd7bccbecc3d/images/11111111-1111-1111-1111-111111111111/CentOS-7.0-1406-x86_64-DVD.iso,if=none,media=cdrom,id=drive-ide0-1-0,readonly=on,format=raw,serial=: Duplicate ID 'drive-ide0-1-0' for drive
>
>Thread-5159::DEBUG::2014-09-11 14:39:09,180::vm::2291::vm.Vm::(_startUnderlyingVm) vmId=`5974b4fc-d37d-49a1-a102-6ab68775ce07`::_ongoingCreations released
>Thread-5159::ERROR::2014-09-11 14:39:09,180::vm::2317::vm.Vm::(_startUnderlyingVm) vmId=`5974b4fc-d37d-49a1-a102-6ab68775ce07`::The vm start process failed
>Traceback (most recent call last):
>  File "/usr/share/vdsm/vm.py", line 2277, in _startUnderlyingVm
>    self._run()
>  File "/usr/share/vdsm/vm.py", line 3224, in _run
>    self._connection.createXML(domxml, flags),
>  File "/usr/lib64/python2.6/site-packages/vdsm/libvirtconnection.py", line 92, in wrapper
>    ret = f(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/libvirt.py", line 2665, in createXML
>    if ret is None:raise libvirtError('virDomainCreateXML() failed', conn=self)
>libvirtError: internal error process exited while connecting to monitor: qemu-kvm: -drive file=/rhev/data-center/mnt/hupe.abes.fr:_ovirt__iso/cdc09bbb-fd7a-4a48-8b6a-cd7bccbecc3d/images/11111111-1111-1111-1111-111111111111/CentOS-7.0-1406-x86_64-DVD.iso,if=none,media=cdrom,id=drive-ide0-1-0,readonly=on,format=raw,serial=: Duplicate ID 'drive-ide0-1-0' for drive
>
>Thread-5159::DEBUG::2014-09-11 14:39:09,189::vm::2759::vm.Vm::(setDownStatus) vmId=`5974b4fc-d37d-49a1-a102-6ab68775ce07`::Changed state to Down: internal error process exited while connecting to monitor: qemu-kvm: -drive file=/rhev/data-center/mnt/hupe.abes.fr:_ovirt__iso/cdc09bbb-fd7a-4a48-8b6a-cd7bccbecc3d/images/11111111-1111-1111-1111-111111111111/CentOS-7.0-1406-x86_64-DVD.iso,if=none,media=cdrom,id=drive-ide0-1-0,readonly=on,format=raw,serial=: Duplicate ID 'drive-ide0-1-0' for drive
>
>Thread-13::DEBUG::2014-09-11 14:39:10,455::BindingXMLRPC::1067::vds::(wrapper) client [10.34.30.46]::call vmGetStats with ('5974b4fc-d37d-49a1-a102-6ab68775ce07',) {}
>Thread-13::DEBUG::2014-09-11 14:39:10,455::BindingXMLRPC::1074::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Down', 'hash': '0', 'exitMessage': "internal error process exited while connecting to monitor: qemu-kvm: -drive file=/rhev/data-center/mnt/hupe.abes.fr:_ovirt__iso/cdc09bbb-fd7a-4a48-8b6a-cd7bccbecc3d/images/11111111-1111-1111-1111-111111111111/CentOS-7.0-1406-x86_64-DVD.iso,if=none,media=cdrom,id=drive-ide0-1-0,readonly=on,format=raw,serial=: Duplicate ID 'drive-ide0-1-0' for drive\n", 'vmId': '5974b4fc-d37d-49a1-a102-6ab68775ce07', 'timeOffset': '0', 'exitCode': 1}]}
>Thread-13::DEBUG::2014-09-11 14:39:10,476::BindingXMLRPC::1067::vds::(wrapper) client [10.34.30.46]::call vmDestroy with ('5974b4fc-d37d-49a1-a102-6ab68775ce07',) {}
>Thread-13::INFO::2014-09-11 14:39:10,476::API::326::vds::(destroy) vmContainerLock acquired by vm 5974b4fc-d37d-49a1-a102-6ab68775ce07
>Thread-13::DEBUG::2014-09-11 14:39:10,476::vm::4689::vm.Vm::(destroy) vmId=`5974b4fc-d37d-49a1-a102-6ab68775ce07`::destroy Called
>Thread-13::INFO::2014-09-11 14:39:10,477::vm::4635::vm.Vm::(releaseVm) vmId=`5974b4fc-d37d-49a1-a102-6ab68775ce07`::Release VM resources
>Thread-13::WARNING::2014-09-11 14:39:10,477::vm::1995::vm.Vm::(_set_lastStatus) vmId=`5974b4fc-d37d-49a1-a102-6ab68775ce07`::trying to set state to Powering down when already Down
>Thread-13::DEBUG::2014-09-11 14:39:10,478::task::595::TaskManager.Task::(_updateState) Task=`0e7b8b8c-e11d-4aad-97bd-1f490e54af93`::moving from state init -> state preparing

Actions: View

Attachments on bug 1109880: 909152 | 909154 | 936543 | 936544