On Mon, Mar 31, 2014 at 01:38:29PM +0300, Gabi C wrote: Would you share an excerpt of your /var/log/vdsm/vdsm.log? Most interesting is the backtrace ending up with this error message.

----- Original Message ----- thanks, but this is engine.log we would find more information on /var/log/vdsm/vdsm.log the host that tried to run the vm (virtual6)

OOps, my bad! here it is: Thread-130::DEBUG::2014-03-31 14:31:00,570::BindingXMLRPC::1067::vds::(wrapper) client [10.125.1.171]::call vmCreate with ({'acpiEnable': 'true', 'emulatedMachine': 'pc-1.0', 'vmId': '2f50cbb4-f80f-4761-bb0d-1d351f497af7', 'memGuaranteedSize': 1024, 'spiceSslCipherSuite': 'DEFAULT', 'timeOffset': '0', 'cpuType': 'Conroe', 'smp': '1', 'custom': {'device_7a09b642-7018-43b8-9938-33432b99cdc1device_dce622cc-29fa-431d-b10f-677903ffebbadevice_156942ac-5c99-496b-8c6a-3ffab96c3164device_e2e8af70-760d-4d07-b27e-cbbcb638affb': 'VmDevice {vmId=2f50cbb4-f80f-4761-bb0d-1d351f497af7, deviceId=e2e8af70-760d-4d07-b27e-cbbcb638affb, device=ide, type=CONTROLLER, bootOrder=0, specParams={}, address={bus=0x00, domain=0x0000, type=pci, slot=0x01, function=0x1}, managed=false, plugged=true, readOnly=false, deviceAlias=ide0, customProperties={}, snapshotId=null}', 'device_7a09b642-7018-43b8-9938-33432b99cdc1': 'VmDevice {vmId=2f50cbb4-f80f-4761-bb0d-1d351f497af7, deviceId=7a09b642-7018-43b8-9938-33432b99cdc1, device=unix, type=CHANNEL, bootOrder=0, specParams={}, address={port=1, bus=0, controller=0, type=virtio-serial}, managed=false, plugged=true, readOnly=false, deviceAlias=channel0, customProperties={}, snapshotId=null}', 'device_7a09b642-7018-43b8-9938-33432b99cdc1device_dce622cc-29fa-431d-b10f-677903ffebbadevice_156942ac-5c99-496b-8c6a-3ffab96c3164device_e2e8af70-760d-4d07-b27e-cbbcb638affbdevice_87060fa4-d4d9-4140-9915-73babd76fc12': 'VmDevice {vmId=2f50cbb4-f80f-4761-bb0d-1d351f497af7, deviceId=87060fa4-d4d9-4140-9915-73babd76fc12, device=virtio-serial, type=CONTROLLER, bootOrder=0, specParams={}, address={bus=0x00, domain=0x0000, type=pci, slot=0x04, function=0x0}, managed=false, plugged=true, readOnly=false, deviceAlias=virtio-serial0, customProperties={}, snapshotId=null}', 'device_7a09b642-7018-43b8-9938-33432b99cdc1device_dce622cc-29fa-431d-b10f-677903ffebbadevice_156942ac-5c99-496b-8c6a-3ffab96c3164': 'VmDevice {vmId=2f50cbb4-f80f-4761-bb0d-1d351f497af7, deviceId=156942ac-5c99-496b-8c6a-3ffab96c3164, device=spicevmc, type=CHANNEL, bootOrder=0, specParams={}, address={port=3, bus=0, controller=0, type=virtio-serial}, managed=false, plugged=true, readOnly=false, deviceAlias=channel2, customProperties={}, snapshotId=null}', 'device_7a09b642-7018-43b8-9938-33432b99cdc1device_dce622cc-29fa-431d-b10f-677903ffebba': 'VmDevice {vmId=2f50cbb4-f80f-4761-bb0d-1d351f497af7, deviceId=dce622cc-29fa-431d-b10f-677903ffebba, device=unix, type=CHANNEL, bootOrder=0, specParams={}, address={port=2, bus=0, controller=0, type=virtio-serial}, managed=false, plugged=true, readOnly=false, deviceAlias=channel1, customProperties={}, snapshotId=null}'}, 'vmType': 'kvm', 'memSize': 10240, 'smpCoresPerSocket': '1', 'vmName': 'satelit', 'nice': '0', 'smartcardEnable': 'false', 'keyboardLayout': 'en-us', 'kvmEnable': 'true', 'pitReinjection': 'false', 'transparentHugePages': 'true', 'devices': [{'device': 'qxl', 'specParams': {'vram': '32768', 'ram': '65536', 'heads': '1'}, 'type': 'video', 'deviceId': '21fbf3bc-a4e0-4706-a2f2-af14f3433a2d', 'address': {'slot': '0x02', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}}, {'index': '2', 'iface': 'ide', 'bootOrder': '2', 'specParams': {'path': ''}, 'readonly': 'true', 'deviceId': 'af3420c5-b179-4761-ac69-85831cee3b49', 'address': {'bus': '1', 'controller': '0', 'type': 'drive', 'target': '0', 'unit': '0'}, 'device': 'cdrom', 'shared': 'false', 'path': '', 'type': 'disk'}, {'index': 0, 'iface': 'virtio', 'format': 'raw', 'bootOrder': '1', 'poolID': '5849b030-626e-47cb-ad90-3ce782d831b3', 'volumeID': '82231f1f-2c7a-4aee-a596-af209fe5e081', 'imageID': 'faa6b382-eaa7-48d4-80fb-3e5999e1a167', 'specParams': {}, 'readonly': 'false', 'domainID': '041e8dbe-f405-4aca-bb78-3bf3cc7dc190', 'optional': 'false', 'deviceId': 'faa6b382-eaa7-48d4-80fb-3e5999e1a167', 'address': {'slot': '0x05', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'disk', 'shared': 'false', 'propagateErrors': 'off', 'type': 'disk'}, {'nicModel': 'pv', 'macAddr': '00:1a:4a:69:90:dd', 'linkActive': 'true', 'network': 'VPO_IPPROXY', 'filter': 'vdsm-no-mac-spoofing', 'specParams': {'inbound': {'average': 25600, 'peak': 26880, 'burst': 256000}, 'outbound': {'average': 25600, 'peak': 26880, 'burst': 256000}}, 'deviceId': '10591bf3-0131-480a-8f89-5b8db7d49cd8', 'address': {'slot': '0x07', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'bridge', 'type': 'interface'}, {'device': 'memballoon', 'specParams': {'model': 'virtio'}, 'type': 'balloon', 'deviceId': 'b9561cf2-37f0-4e64-bc7b-8c1921c06f9b'}, {'index': '0', 'specParams': {}, 'deviceId': 'd02fc85d-4862-4e0f-a7c5-eadce3509935', 'address': {'slot': '0x03', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'scsi', 'model': 'virtio-scsi', 'type': 'controller'}], 'spiceSecureChannels': 'smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard', 'display': 'qxl'},) {} Thread-130::INFO::2014-03-31 14:31:00,578::API::668::vds::(_getNetworkIp) network None: using 0 Thread-130::INFO::2014-03-31 14:31:00,578::clientIF::366::vds::(createVm) vmContainerLock acquired by vm 2f50cbb4-f80f-4761-bb0d-1d351f497af7 Thread-130::DEBUG::2014-03-31 14:31:00,582::clientIF::379::vds::(createVm) Total desktops after creation of 2f50cbb4-f80f-4761-bb0d-1d351f497af7 is 2 Thread-130::DEBUG::2014-03-31 14:31:00,582::BindingXMLRPC::1074::vds::(wrapper) return vmCreate with {'status': {'message': 'Done', 'code': 0}, 'vmList': {'status': 'WaitForLaunch', 'acpiEnable': 'true', 'emulatedMachine': 'pc-1.0', 'vmId': '2f50cbb4-f80f-4761-bb0d-1d351f497af7', 'pid': '0', 'memGuaranteedSize': 1024, 'timeOffset': '0', 'keyboardLayout': 'en-us', 'displayPort': '-1', 'displaySecurePort': '-1', 'spiceSslCipherSuite': 'DEFAULT', 'cpuType': 'Conroe', 'custom': {'device_7a09b642-7018-43b8-9938-33432b99cdc1device_dce622cc-29fa-431d-b10f-677903ffebbadevice_156942ac-5c99-496b-8c6a-3ffab96c3164device_e2e8af70-760d-4d07-b27e-cbbcb638affb': 'VmDevice {vmId=2f50cbb4-f80f-4761-bb0d-1d351f497af7, deviceId=e2e8af70-760d-4d07-b27e-cbbcb638affb, device=ide, type=CONTROLLER, bootOrder=0, specParams={}, address={bus=0x00, domain=0x0000, type=pci, slot=0x01, function=0x1}, managed=false, plugged=true, readOnly=false, deviceAlias=ide0, customProperties={}, snapshotId=null}', 'device_7a09b642-7018-43b8-9938-33432b99cdc1': 'VmDevice {vmId=2f50cbb4-f80f-4761-bb0d-1d351f497af7, deviceId=7a09b642-7018-43b8-9938-33432b99cdc1, device=unix, type=CHANNEL, bootOrder=0, specParams={}, address={port=1, bus=0, controller=0, type=virtio-serial}, managed=false, plugged=true, readOnly=false, deviceAlias=channel0, customProperties={}, snapshotId=null}', 'device_7a09b642-7018-43b8-9938-33432b99cdc1device_dce622cc-29fa-431d-b10f-677903ffebbadevice_156942ac-5c99-496b-8c6a-3ffab96c3164device_e2e8af70-760d-4d07-b27e-cbbcb638affbdevice_87060fa4-d4d9-4140-9915-73babd76fc12': 'VmDevice {vmId=2f50cbb4-f80f-4761-bb0d-1d351f497af7, deviceId=87060fa4-d4d9-4140-9915-73babd76fc12, device=virtio-serial, type=CONTROLLER, bootOrder=0, specParams={}, address={bus=0x00, domain=0x0000, type=pci, slot=0x04, function=0x0}, managed=false, plugged=true, readOnly=false, deviceAlias=virtio-serial0, customProperties={}, snapshotId=null}', 'device_7a09b642-7018-43b8-9938-33432b99cdc1device_dce622cc-29fa-431d-b10f-677903ffebbadevice_156942ac-5c99-496b-8c6a-3ffab96c3164': 'VmDevice {vmId=2f50cbb4-f80f-4761-bb0d-1d351f497af7, deviceId=156942ac-5c99-496b-8c6a-3ffab96c3164, device=spicevmc, type=CHANNEL, bootOrder=0, specParams={}, address={port=3, bus=0, controller=0, type=virtio-serial}, managed=false, plugged=true, readOnly=false, deviceAlias=channel2, customProperties={}, snapshotId=null}', 'device_7a09b642-7018-43b8-9938-33432b99cdc1device_dce622cc-29fa-431d-b10f-677903ffebba': 'VmDevice {vmId=2f50cbb4-f80f-4761-bb0d-1d351f497af7, deviceId=dce622cc-29fa-431d-b10f-677903ffebba, device=unix, type=CHANNEL, bootOrder=0, specParams={}, address={port=2, bus=0, controller=0, type=virtio-serial}, managed=false, plugged=true, readOnly=false, deviceAlias=channel1, customProperties={}, snapshotId=null}'}, 'clientIp': '', 'nicModel': 'rtl8139,pv', 'smartcardEnable': 'false', 'kvmEnable': 'true', 'pitReinjection': 'false', 'transparentHugePages': 'true', 'devices': [{'device': 'qxl', 'specParams': {'vram': '32768', 'ram': '65536', 'heads': '1'}, 'type': 'video', 'deviceId': '21fbf3bc-a4e0-4706-a2f2-af14f3433a2d', 'address': {'slot': '0x02', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}}, {'index': '2', 'iface': 'ide', 'bootOrder': '2', 'specParams': {'path': ''}, 'readonly': 'true', 'deviceId': 'af3420c5-b179-4761-ac69-85831cee3b49', 'address': {'bus': '1', 'controller': '0', 'type': 'drive', 'target': '0', 'unit': '0'}, 'device': 'cdrom', 'shared': 'false', 'path': '', 'type': 'disk'}, {'index': 0, 'iface': 'virtio', 'format': 'raw', 'bootOrder': '1', 'poolID': '5849b030-626e-47cb-ad90-3ce782d831b3', 'volumeID': '82231f1f-2c7a-4aee-a596-af209fe5e081', 'imageID': 'faa6b382-eaa7-48d4-80fb-3e5999e1a167', 'specParams': {}, 'readonly': 'false', 'domainID': '041e8dbe-f405-4aca-bb78-3bf3cc7dc190', 'optional': 'false', 'deviceId': 'faa6b382-eaa7-48d4-80fb-3e5999e1a167', 'address': {'slot': '0x05', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'disk', 'shared': 'false', 'propagateErrors': 'off', 'type': 'disk'}, {'nicModel': 'pv', 'macAddr': '00:1a:4a:69:90:dd', 'linkActive': 'true', 'network': 'VPO_IPPROXY', 'filter': 'vdsm-no-mac-spoofing', 'specParams': {'inbound': {'average': 25600, 'peak': 26880, 'burst': 256000}, 'outbound': {'average': 25600, 'peak': 26880, 'burst': 256000}}, 'deviceId': '10591bf3-0131-480a-8f89-5b8db7d49cd8', 'address': {'slot': '0x07', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'bridge', 'type': 'interface'}, {'device': 'memballoon', 'specParams': {'model': 'virtio'}, 'type': 'balloon', 'deviceId': 'b9561cf2-37f0-4e64-bc7b-8c1921c06f9b'}, {'index': '0', 'specParams': {}, 'deviceId': 'd02fc85d-4862-4e0f-a7c5-eadce3509935', 'address': {'slot': '0x03', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'scsi', 'model': 'virtio-scsi', 'type': 'controller'}], 'smp': '1', 'vmType': 'kvm', 'memSize': 10240, 'displayIp': '0', 'spiceSecureChannels': 'smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard', 'smpCoresPerSocket': '1', 'vmName': 'satelit', 'display': 'qxl', 'nice': '0'}} Thread-469::DEBUG::2014-03-31 14:31:00,584::vm::2242::vm.Vm::(_startUnderlyingVm) vmId=`2f50cbb4-f80f-4761-bb0d-1d351f497af7`::Start Thread-469::DEBUG::2014-03-31 14:31:00,584::vm::2246::vm.Vm::(_startUnderlyingVm) vmId=`2f50cbb4-f80f-4761-bb0d-1d351f497af7`::_ongoingCreations acquired Thread-469::INFO::2014-03-31 14:31:00,585::vm::3097::vm.Vm::(_run) vmId=`2f50cbb4-f80f-4761-bb0d-1d351f497af7`::VM wrapper has started Thread-469::DEBUG::2014-03-31 14:31:00,585::task::595::TaskManager.Task::(_updateState) Task=`afd2f80d-4245-4368-aa74-ce9326e49816`::moving from state init -> state preparing Thread-469::INFO::2014-03-31 14:31:00,585::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='041e8dbe-f405-4aca-bb78-3bf3cc7dc190', spUUID='5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID='faa6b382-eaa7-48d4-80fb-3e5999e1a167', volUUID='82231f1f-2c7a-4aee-a596-af209fe5e081', options=None) Thread-469::INFO::2014-03-31 14:31:00,590::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '128230096896', 'apparentsize': '161061273600'} Thread-469::DEBUG::2014-03-31 14:31:00,590::task::1185::TaskManager.Task::(prepare) Task=`afd2f80d-4245-4368-aa74-ce9326e49816`::finished: {'truesize': '128230096896', 'apparentsize': '161061273600'} Thread-469::DEBUG::2014-03-31 14:31:00,590::task::595::TaskManager.Task::(_updateState) Task=`afd2f80d-4245-4368-aa74-ce9326e49816`::moving from state preparing -> state finished Thread-469::DEBUG::2014-03-31 14:31:00,590::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-469::DEBUG::2014-03-31 14:31:00,590::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-469::DEBUG::2014-03-31 14:31:00,591::task::990::TaskManager.Task::(_decref) Task=`afd2f80d-4245-4368-aa74-ce9326e49816`::ref 0 aborting False Thread-469::INFO::2014-03-31 14:31:00,591::clientIF::324::vds::(prepareVolumePath) prepared volume path: Thread-469::DEBUG::2014-03-31 14:31:00,591::task::595::TaskManager.Task::(_updateState) Task=`ebc21d48-03ca-4764-a5eb-6544c680fb6c`::moving from state init -> state preparing Thread-469::INFO::2014-03-31 14:31:00,591::logUtils::44::dispatcher::(wrapper) Run and protect: prepareImage(sdUUID='041e8dbe-f405-4aca-bb78-3bf3cc7dc190', spUUID='5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID='faa6b382-eaa7-48d4-80fb-3e5999e1a167', leafUUID='82231f1f-2c7a-4aee-a596-af209fe5e081') Thread-469::DEBUG::2014-03-31 14:31:00,592::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.041e8dbe-f405-4aca-bb78-3bf3cc7dc190`ReqID=`6bd72828-e18d-4461-822d-4b5c80152dce`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3237' at 'prepareImage' Thread-469::DEBUG::2014-03-31 14:31:00,592::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.041e8dbe-f405-4aca-bb78-3bf3cc7dc190' for lock type 'shared' Thread-469::DEBUG::2014-03-31 14:31:00,592::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.041e8dbe-f405-4aca-bb78-3bf3cc7dc190' is free. Now locking as 'shared' (1 active user) Thread-469::DEBUG::2014-03-31 14:31:00,592::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.041e8dbe-f405-4aca-bb78-3bf3cc7dc190`ReqID=`6bd72828-e18d-4461-822d-4b5c80152dce`::Granted request Thread-469::DEBUG::2014-03-31 14:31:00,593::task::827::TaskManager.Task::(resourceAcquired) Task=`ebc21d48-03ca-4764-a5eb-6544c680fb6c`::_resourcesAcquired: Storage.041e8dbe-f405-4aca-bb78-3bf3cc7dc190 (shared) Thread-469::DEBUG::2014-03-31 14:31:00,593::task::990::TaskManager.Task::(_decref) Task=`ebc21d48-03ca-4764-a5eb-6544c680fb6c`::ref 1 aborting False Thread-469::WARNING::2014-03-31 14:31:00,600::fileUtils::167::Storage.fileUtils::(createdir) Dir /var/run/vdsm/storage/041e8dbe-f405-4aca-bb78-3bf3cc7dc190 already exists Thread-469::DEBUG::2014-03-31 14:31:00,600::fileSD::446::Storage.StorageDomain::(createImageLinks) img run dir already exists: /var/run/vdsm/storage/041e8dbe-f405-4aca-bb78-3bf3cc7dc190/faa6b382-eaa7-48d4-80fb-3e5999e1a167 Thread-469::DEBUG::2014-03-31 14:31:00,601::fileVolume::529::Storage.Volume::(validateVolumePath) validate path for 82231f1f-2c7a-4aee-a596-af209fe5e081 Thread-469::INFO::2014-03-31 14:31:00,602::logUtils::47::dispatcher::(wrapper) Run and protect: prepareImage, Return response: {'info': {'domainID': '041e8dbe-f405-4aca-bb78-3bf3cc7dc190', 'volType': 'path', 'leaseOffset': 0, 'path': '/rhev/data-center/mnt/glusterSD/10.125.1.194:gluster__data2/041e8dbe-f405-4aca-bb78-3bf3cc7dc190/images/faa6b382-eaa7-48d4-80fb-3e5999e1a167/82231f1f-2c7a-4aee-a596-af209fe5e081', 'volumeID': '82231f1f-2c7a-4aee-a596-af209fe5e081', 'leasePath': '/rhev/data-center/mnt/glusterSD/10.125.1.194:gluster__data2/041e8dbe-f405-4aca-bb78-3bf3cc7dc190/images/faa6b382-eaa7-48d4-80fb-3e5999e1a167/82231f1f-2c7a-4aee-a596-af209fe5e081.lease', 'imageID': 'faa6b382-eaa7-48d4-80fb-3e5999e1a167'}, 'path': '/rhev/data-center/mnt/glusterSD/10.125.1.194:gluster__data2/041e8dbe-f405-4aca-bb78-3bf3cc7dc190/images/faa6b382-eaa7-48d4-80fb-3e5999e1a167/82231f1f-2c7a-4aee-a596-af209fe5e081', 'imgVolumesInfo': [{'domainID': '041e8dbe-f405-4aca-bb78-3bf3cc7dc190', 'volType': 'path', 'leaseOffset': 0, 'path': '/rhev/data-center/mnt/glusterSD/10.125.1.194:gluster__data2/041e8dbe-f405-4aca-bb78-3bf3cc7dc190/images/faa6b382-eaa7-48d4-80fb-3e5999e1a167/82231f1f-2c7a-4aee-a596-af209fe5e081', 'volumeID': '82231f1f-2c7a-4aee-a596-af209fe5e081', 'leasePath': '/rhev/data-center/mnt/glusterSD/10.125.1.194:gluster__data2/041e8dbe-f405-4aca-bb78-3bf3cc7dc190/images/faa6b382-eaa7-48d4-80fb-3e5999e1a167/82231f1f-2c7a-4aee-a596-af209fe5e081.lease', 'imageID': 'faa6b382-eaa7-48d4-80fb-3e5999e1a167'}]} Thread-469::DEBUG::2014-03-31 14:31:00,603::task::1185::TaskManager.Task::(prepare) Task=`ebc21d48-03ca-4764-a5eb-6544c680fb6c`::finished: {'info': {'domainID': '041e8dbe-f405-4aca-bb78-3bf3cc7dc190', 'volType': 'path', 'leaseOffset': 0, 'path': '/rhev/data-center/mnt/glusterSD/10.125.1.194:gluster__data2/041e8dbe-f405-4aca-bb78-3bf3cc7dc190/images/faa6b382-eaa7-48d4-80fb-3e5999e1a167/82231f1f-2c7a-4aee-a596-af209fe5e081', 'volumeID': '82231f1f-2c7a-4aee-a596-af209fe5e081', 'leasePath': '/rhev/data-center/mnt/glusterSD/10.125.1.194:gluster__data2/041e8dbe-f405-4aca-bb78-3bf3cc7dc190/images/faa6b382-eaa7-48d4-80fb-3e5999e1a167/82231f1f-2c7a-4aee-a596-af209fe5e081.lease', 'imageID': 'faa6b382-eaa7-48d4-80fb-3e5999e1a167'}, 'path': '/rhev/data-center/mnt/glusterSD/10.125.1.194:gluster__data2/041e8dbe-f405-4aca-bb78-3bf3cc7dc190/images/faa6b382-eaa7-48d4-80fb-3e5999e1a167/82231f1f-2c7a-4aee-a596-af209fe5e081', 'imgVolumesInfo': [{'domainID': '041e8dbe-f405-4aca-bb78-3bf3cc7dc190', 'volType': 'path', 'leaseOffset': 0, 'path': '/rhev/data-center/mnt/glusterSD/10.125.1.194:gluster__data2/041e8dbe-f405-4aca-bb78-3bf3cc7dc190/images/faa6b382-eaa7-48d4-80fb-3e5999e1a167/82231f1f-2c7a-4aee-a596-af209fe5e081', 'volumeID': '82231f1f-2c7a-4aee-a596-af209fe5e081', 'leasePath': '/rhev/data-center/mnt/glusterSD/10.125.1.194:gluster__data2/041e8dbe-f405-4aca-bb78-3bf3cc7dc190/images/faa6b382-eaa7-48d4-80fb-3e5999e1a167/82231f1f-2c7a-4aee-a596-af209fe5e081.lease', 'imageID': 'faa6b382-eaa7-48d4-80fb-3e5999e1a167'}]} Thread-469::DEBUG::2014-03-31 14:31:00,603::task::595::TaskManager.Task::(_updateState) Task=`ebc21d48-03ca-4764-a5eb-6544c680fb6c`::moving from state preparing -> state finished Thread-469::DEBUG::2014-03-31 14:31:00,603::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.041e8dbe-f405-4aca-bb78-3bf3cc7dc190': < ResourceRef 'Storage.041e8dbe-f405-4aca-bb78-3bf3cc7dc190', isValid: 'True' obj: 'None'>} Thread-469::DEBUG::2014-03-31 14:31:00,603::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-469::DEBUG::2014-03-31 14:31:00,603::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.041e8dbe-f405-4aca-bb78-3bf3cc7dc190' Thread-469::DEBUG::2014-03-31 14:31:00,604::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.041e8dbe-f405-4aca-bb78-3bf3cc7dc190' (0 active users) Thread-469::DEBUG::2014-03-31 14:31:00,604::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.041e8dbe-f405-4aca-bb78-3bf3cc7dc190' is free, finding out if anyone is waiting for it. Thread-469::DEBUG::2014-03-31 14:31:00,604::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.041e8dbe-f405-4aca-bb78-3bf3cc7dc190', Clearing records. Thread-469::DEBUG::2014-03-31 14:31:00,604::task::990::TaskManager.Task::(_decref) Task=`ebc21d48-03ca-4764-a5eb-6544c680fb6c`::ref 0 aborting False Thread-469::INFO::2014-03-31 14:31:00,604::clientIF::324::vds::(prepareVolumePath) prepared volume path: /rhev/data-center/mnt/glusterSD/10.125.1.194: gluster__data2/041e8dbe-f405-4aca-bb78-3bf3cc7dc190/images/faa6b382-eaa7-48d4-80fb-3e5999e1a167/82231f1f-2c7a-4aee-a596-af209fe5e081 Thread-469::DEBUG::2014-03-31 14:31:00,613::vm::2263::vm.Vm::(_startUnderlyingVm) vmId=`2f50cbb4-f80f-4761-bb0d-1d351f497af7`::_ongoingCreations released Thread-469::ERROR::2014-03-31 14:31:00,614::vm::2289::vm.Vm::(_startUnderlyingVm) vmId=`2f50cbb4-f80f-4761-bb0d-1d351f497af7`::The vm start process failed Traceback (most recent call last): File "/usr/share/vdsm/vm.py", line 2249, in _startUnderlyingVm self._run() File "/usr/share/vdsm/vm.py", line 3135, in _run domxml = hooks.before_vm_start(self._buildCmdLine(), self.conf) File "/usr/share/vdsm/vm.py", line 2965, in _buildCmdLine self._appendDevices(domxml) File "/usr/share/vdsm/vm.py", line 2922, in _appendDevices deviceXML = dev.getXML().toxml(encoding='utf-8') File "/usr/lib64/python2.7/xml/dom/minidom.py", line 46, in toxml return self.toprettyxml("", "", encoding) File "/usr/lib64/python2.7/xml/dom/minidom.py", line 60, in toprettyxml self.writexml(writer, "", indent, newl) File "/usr/share/vdsm/vm.py", line 5268, in __hacked_writexml node.writexml(writer, indent + addindent, addindent, newl) File "/usr/share/vdsm/vm.py", line 5268, in __hacked_writexml node.writexml(writer, indent + addindent, addindent, newl) File "/usr/share/vdsm/vm.py", line 5256, in __hacked_writexml xml.dom.minidom._write_data(writer, attrs[a_name].value) File "/usr/lib64/python2.7/xml/dom/minidom.py", line 296, in _write_data data = data.replace("&", "&amp;").replace("<", "&lt;"). \ AttributeError: 'int' object has no attribute 'replace' Thread-469::DEBUG::2014-03-31 14:31:00,618::vm::2731::vm.Vm::(setDownStatus) vmId=`2f50cbb4-f80f-4761-bb0d-1d351f497af7`::Changed state to Down: 'int' object has no attribute 'replace' Thread-130::DEBUG::2014-03-31 14:31:02,693::BindingXMLRPC::1067::vds::(wrapper) client [10.125.1.171]::call vmGetStats with ('2f50cbb4-f80f-4761-bb0d-1d351f497af7',) {} Thread-130::DEBUG::2014-03-31 14:31:02,694::BindingXMLRPC::1074::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Down', 'hash': '0', 'exitMessage': "'int' object has no attribute 'replace'", 'vmId': '2f50cbb4-f80f-4761-bb0d-1d351f497af7', 'timeOffset': '0', 'exitCode': 1}]} Thread-130::DEBUG::2014-03-31 14:31:02,707::BindingXMLRPC::1067::vds::(wrapper) client [10.125.1.171]::call vmDestroy with ('2f50cbb4-f80f-4761-bb0d-1d351f497af7',) {} Thread-130::INFO::2014-03-31 14:31:02,708::API::327::vds::(destroy) vmContainerLock acquired by vm 2f50cbb4-f80f-4761-bb0d-1d351f497af7 Thread-130::DEBUG::2014-03-31 14:31:02,708::vm::4629::vm.Vm::(destroy) vmId=`2f50cbb4-f80f-4761-bb0d-1d351f497af7`::destroy Called Thread-130::INFO::2014-03-31 14:31:02,708::vm::4575::vm.Vm::(releaseVm) vmId=`2f50cbb4-f80f-4761-bb0d-1d351f497af7`::Release VM resources Thread-130::WARNING::2014-03-31 14:31:02,708::vm::1967::vm.Vm::(_set_lastStatus) vmId=`2f50cbb4-f80f-4761-bb0d-1d351f497af7`::trying to set state to Powering down when already Down Thread-130::DEBUG::2014-03-31 14:31:02,709::task::595::TaskManager.Task::(_updateState) Task=`e42042ca-c4fe-467b-8810-99099482dfdb`::moving from state init -> state preparing Thread-130::INFO::2014-03-31 14:31:02,709::logUtils::44::dispatcher::(wrapper) Run and protect: teardownImage(sdUUID='041e8dbe-f405-4aca-bb78-3bf3cc7dc190', spUUID='5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID='faa6b382-eaa7-48d4-80fb-3e5999e1a167', volUUID=None) Thread-130::DEBUG::2014-03-31 14:31:02,710::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.041e8dbe-f405-4aca-bb78-3bf3cc7dc190`ReqID=`94ad1f7a-b152-49ae-ba64-83ffeeb82ee1`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3285' at 'teardownImage' Thread-130::DEBUG::2014-03-31 14:31:02,710::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.041e8dbe-f405-4aca-bb78-3bf3cc7dc190' for lock type 'shared' Thread-130::DEBUG::2014-03-31 14:31:02,710::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.041e8dbe-f405-4aca-bb78-3bf3cc7dc190' is free. Now locking as 'shared' (1 active user) Thread-130::DEBUG::2014-03-31 14:31:02,711::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.041e8dbe-f405-4aca-bb78-3bf3cc7dc190`ReqID=`94ad1f7a-b152-49ae-ba64-83ffeeb82ee1`::Granted request Thread-130::DEBUG::2014-03-31 14:31:02,711::task::827::TaskManager.Task::(resourceAcquired) Task=`e42042ca-c4fe-467b-8810-99099482dfdb`::_resourcesAcquired: Storage.041e8dbe-f405-4aca-bb78-3bf3cc7dc190 (shared) Thread-130::DEBUG::2014-03-31 14:31:02,711::task::990::TaskManager.Task::(_decref) Task=`e42042ca-c4fe-467b-8810-99099482dfdb`::ref 1 aborting False Thread-130::INFO::2014-03-31 14:31:02,712::logUtils::47::dispatcher::(wrapper) Run and protect: teardownImage, Return response: None Thread-130::DEBUG::2014-03-31 14:31:02,712::task::1185::TaskManager.Task::(prepare) Task=`e42042ca-c4fe-467b-8810-99099482dfdb`::finished: None Thread-130::DEBUG::2014-03-31 14:31:02,713::task::595::TaskManager.Task::(_updateState) Task=`e42042ca-c4fe-467b-8810-99099482dfdb`::moving from state preparing -> state finished Thread-130::DEBUG::2014-03-31 14:31:02,713::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.041e8dbe-f405-4aca-bb78-3bf3cc7dc190': < ResourceRef 'Storage.041e8dbe-f405-4aca-bb78-3bf3cc7dc190', isValid: 'True' obj: 'None'>} Thread-130::DEBUG::2014-03-31 14:31:02,713::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-130::DEBUG::2014-03-31 14:31:02,713::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.041e8dbe-f405-4aca-bb78-3bf3cc7dc190' Thread-130::DEBUG::2014-03-31 14:31:02,714::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.041e8dbe-f405-4aca-bb78-3bf3cc7dc190' (0 active users) Thread-130::DEBUG::2014-03-31 14:31:02,714::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.041e8dbe-f405-4aca-bb78-3bf3cc7dc190' is free, finding out if anyone is waiting for it. Thread-130::DEBUG::2014-03-31 14:31:02,714::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.041e8dbe-f405-4aca-bb78-3bf3cc7dc190', Clearing records. Thread-130::DEBUG::2014-03-31 14:31:02,714::task::990::TaskManager.Task::(_decref) Task=`e42042ca-c4fe-467b-8810-99099482dfdb`::ref 0 aborting False Thread-130::WARNING::2014-03-31 14:31:02,715::utils::129::root::(rmFile) File: /var/lib/libvirt/qemu/channels/2f50cbb4-f80f-4761-bb0d-1d351f497af7.com.redhat.rhevm.vdsm already removed Thread-130::WARNING::2014-03-31 14:31:02,716::utils::129::root::(rmFile) File: /var/lib/libvirt/qemu/channels/2f50cbb4-f80f-4761-bb0d-1d351f497af7.org.qemu.guest_agent.0 already removed Thread-130::DEBUG::2014-03-31 14:31:02,717::task::595::TaskManager.Task::(_updateState) Task=`2a6b057d-fe6e-4768-b32b-986295e416f5`::moving from state init -> state preparing Thread-130::INFO::2014-03-31 14:31:02,717::logUtils::44::dispatcher::(wrapper) Run and protect: inappropriateDevices(thiefId='2f50cbb4-f80f-4761-bb0d-1d351f497af7') Thread-130::INFO::2014-03-31 14:31:02,718::logUtils::47::dispatcher::(wrapper) Run and protect: inappropriateDevices, Return response: None Thread-130::DEBUG::2014-03-31 14:31:02,718::task::1185::TaskManager.Task::(prepare) Task=`2a6b057d-fe6e-4768-b32b-986295e416f5`::finished: None Thread-130::DEBUG::2014-03-31 14:31:02,718::task::595::TaskManager.Task::(_updateState) Task=`2a6b057d-fe6e-4768-b32b-986295e416f5`::moving from state preparing -> state finished Thread-130::DEBUG::2014-03-31 14:31:02,718::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-130::DEBUG::2014-03-31 14:31:02,718::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-130::DEBUG::2014-03-31 14:31:02,719::task::990::TaskManager.Task::(_decref) Task=`2a6b057d-fe6e-4768-b32b-986295e416f5`::ref 0 aborting False Thread-130::DEBUG::2014-03-31 14:31:02,719::vm::4623::vm.Vm::(deleteVm) vmId=`2f50cbb4-f80f-4761-bb0d-1d351f497af7`::Total desktops after destroy of 2f50cbb4-f80f-4761-bb0d-1d351f497af7 is 1 Thread-130::DEBUG::2014-03-31 14:31:02,720::BindingXMLRPC::1074::vds::(wrapper) return vmDestroy with {'status': {'message': 'Machine destroyed', 'code': 0}} Thread-23::DEBUG::2014-03-31 14:31:02,742::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.125.1.193:_mnt_storage__filer1_export__nfs1_export/62f795ed-486c-443d-93e9-2c16595fe546/dom_md/metadata bs=4096 count=1' (cwd None) Thread-23::DEBUG::2014-03-31 14:31:02,837::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n491 bytes (491 B) copied, 0.000564355 s, 870 kB/s\n'; <rc> = 0 Thread-21::DEBUG::2014-03-31 14:31:02,870::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.125.1.193:_mnt_storage__filer1_export__nfs2_iso/b157f887-ae9a-4337-8c55-7c8a9df017bb/dom_md/metadata bs=4096 count=1' (cwd None) Thread-21::DEBUG::2014-03-31 14:31:02,905::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n369 bytes (369 B) copied, 0.000450599 s, 819 kB/s\n'; <rc> = 0 Thread-20::DEBUG::2014-03-31 14:31:05,798::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/glusterSD/10.125.1.194:gluster__data2/041e8dbe-f405-4aca-bb78-3bf3cc7dc190/dom_md/metadata bs=4096 count=1' (cwd None) Thread-20::DEBUG::2014-03-31 14:31:05,825::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n608 bytes (608 B) copied, 0.000467098 s, 1.3 MB/s\n'; <rc> = 0 Thread-130::DEBUG::2014-03-31 14:31:05,835::task::595::TaskManager.Task::(_updateState) Task=`4ccb0515-1051-4084-87a8-5f672be6755b`::moving from state init -> state preparing Thread-130::INFO::2014-03-31 14:31:05,835::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None) Thread-130::INFO::2014-03-31 14:31:05,835::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'041e8dbe-f405-4aca-bb78-3bf3cc7dc190': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000467098', 'lastCheck': '0.0', 'valid': True}, 'b157f887-ae9a-4337-8c55-7c8a9df017bb': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000450599', 'lastCheck': '2.9', 'valid': True}, '5fe658b1-43ff-4bfd-97d6-28217cf415df': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000212863', 'lastCheck': '8.5', 'valid': True}, '62f795ed-486c-443d-93e9-2c16595fe546': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000564355', 'lastCheck': '3.0', 'valid': True}} Thread-130::DEBUG::2014-03-31 14:31:05,836::task::1185::TaskManager.Task::(prepare) Task=`4ccb0515-1051-4084-87a8-5f672be6755b`::finished: {'041e8dbe-f405-4aca-bb78-3bf3cc7dc190': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000467098', 'lastCheck': '0.0', 'valid': True}, 'b157f887-ae9a-4337-8c55-7c8a9df017bb': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000450599', 'lastCheck': '2.9', 'valid': True}, '5fe658b1-43ff-4bfd-97d6-28217cf415df': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000212863', 'lastCheck': '8.5', 'valid': True}, '62f795ed-486c-443d-93e9-2c16595fe546': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000564355', 'lastCheck': '3.0', 'valid': True}} Thread-130::DEBUG::2014-03-31 14:31:05,836::task::595::TaskManager.Task::(_updateState) Task=`4ccb0515-1051-4084-87a8-5f672be6755b`::moving from state preparing -> state finished Thread-130::DEBUG::2014-03-31 14:31:05,836::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-130::DEBUG::2014-03-31 14:31:05,836::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-130::DEBUG::2014-03-31 14:31:05,836::task::990::TaskManager.Task::(_decref) Task=`4ccb0515-1051-4084-87a8-5f672be6755b`::ref 0 aborting False Thread-22::DEBUG::2014-03-31 14:31:07,355::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/glusterSD/10.125.1.194:gluster__data3/5fe658b1-43ff-4bfd-97d6-28217cf415df/dom_md/metadata bs=4096 count=1' (cwd None) Thread-22::DEBUG::2014-03-31 14:31:07,437::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n653 bytes (653 B) copied, 0.00062957 s, 1.0 MB/s\n'; <rc> = 0 On Mon, Mar 31, 2014 at 2:21 PM, Omer Frenkel <ofrenkel(a)redhat.com&gt; wrote:

....my bad...problem still persist after upgrading node according to the release notes On Mon, Mar 31, 2014 at 4:08 PM, Gabi C <gabicr(a)gmail.com&gt; wrote:

Hello! Has that fix pushed into the repository yet? Seems that removing Qos profiles from the NIC profiles did the trick..VM is up! Thanks guys! On Mon, Mar 31, 2014 at 4:45 PM, Francesco Romani <fromani(a)redhat.com&gt;wrote:

I'll try and let you know, but is a little bit difficult due to the fact that my setup is a production one! On Wed, Apr 2, 2014 at 12:59 AM, Dan Kenigsberg <danken(a)redhat.com&gt; wrote: