Thanks! Here it is: 2014-03-31 13:53:54,737 INFO [org.ovirt.engine.core.bll.RunVmCommand] (ajp--127.0.0.1-8702-20) [787f133c] Lock Acquired to object EngineLock [exclusiveLocks= key: 92fbccc5-1c99-4020-822b-74d43ad214c3 value: VM , sharedLocks= ] 2014-03-31 13:53:54,763 INFO [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (ajp--127.0.0.1-8702-20) [787f133c] START, IsVmDuringInitiatingVDSCommand( vmId = 92fbccc5-1c99-4020-822b-74d43ad214c3), log id: 685abcbf 2014-03-31 13:53:54,767 INFO [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (ajp--127.0.0.1-8702-20) [787f133c] FINISH, IsVmDuringInitiatingVDSCommand, return: false, log id: 685abcbf 2014-03-31 13:53:54,811 INFO [org.ovirt.engine.core.bll.RunVmCommand] (org.ovirt.thread.pool-6-thread-4) [787f133c] Running command: RunVmCommand internal: false. Entities affected : ID: 92fbccc5-1c99-4020-822b-74d43ad214c3 Type: VM 2014-03-31 13:53:54,839 INFO [org.ovirt.engine.core.bll.scheduling.policyunits.HaReservationWeightPolicyUnit] (org.ovirt.thread.pool-6-thread-4) [787f133c] Started HA reservation scoring method 2014-03-31 13:53:54,855 INFO [org.ovirt.engine.core.vdsbroker.CreateVmVDSCommand] (org.ovirt.thread.pool-6-thread-4) [787f133c] START, CreateVmVDSCommand(HostName = virtual6, HostId = e11c37b0-d79d-417b-bd6f-6dc172f7921c, vmId=92fbccc5-1c99-4020-822b-74d43ad214c3, vm=VM [PRTG]), log id: 497b9920 2014-03-31 13:53:54,863 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] (org.ovirt.thread.pool-6-thread-4) [787f133c] START, CreateVDSCommand(HostName = virtual6, HostId = e11c37b0-d79d-417b-bd6f-6dc172f7921c, vmId=92fbccc5-1c99-4020-822b-74d43ad214c3, vm=VM [PRTG]), log id: 7b64d5f2 2014-03-31 13:53:54,923 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] (org.ovirt.thread.pool-6-thread-4) [787f133c] org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand spiceSslCipherSuite=DEFAULT,memSize=2048,kvmEnable=true,smp=1,vmType=kvm,emulatedMachine=pc-1.0,keyboardLayout=en-us,memGuaranteedSize=1365,nice=0,display=qxl,smartcardEnable=false,smpCoresPerSocket=1,spiceSecureChannels=smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard,timeOffset=3600,transparentHugePages=true,vmId=92fbccc5-1c99-4020-822b-74d43ad214c3,devices=[{address={bus=0x00, domain=0x0000, slot=0x02, type=pci, function=0x0}, specParams={vram=32768, heads=1}, device=qxl, type=video, deviceId=e46018f8-fbfc-484d-891a-e7ade9f88c51}, {shared=false, bootOrder=2, iface=ide, index=2, address={unit=0, bus=1, target=0, controller=0, type=drive}, specParams={path=}, path=, device=cdrom, type=disk, readonly=true, deviceId=8eac07a3-d353-43db-b2e3-5f8fe414bdfe}, {shared=false, index=0, volumeID=438299fb-0a72-4005-b0c8-5544eece6dba, propagateErrors=off, format=raw, type=disk, iface=virtio, bootOrder=1, address={bus=0x00, domain=0x0000, slot=0x06, type=pci, function=0x0}, domainID=041e8dbe-f405-4aca-bb78-3bf3cc7dc190, imageID=68051a25-d3de-46b4-9e4b-686d824146bf, specParams={}, optional=false, device=disk, poolID=5849b030-626e-47cb-ad90-3ce782d831b3, readonly=false, deviceId=68051a25-d3de-46b4-9e4b-686d824146bf}, {nicModel=pv, address={bus=0x00, domain=0x0000, slot=0x03, type=pci, function=0x0}, specParams={outbound={peak=26880, burst=256000, average=25600}, inbound={peak=26880, burst=256000, average=25600}}, macAddr=00:1a:4a:69:90:de, device=bridge, linkActive=true, type=interface, filter=vdsm-no-mac-spoofing, network=VPO_IPPROXY, deviceId=553de5f6-e108-4c45-84d2-7a292304211f}, {specParams={model=virtio}, device=memballoon, type=balloon, deviceId=68c759aa-6266-432c-9b8b-7a4b215eee57}, {index=0, model=virtio-scsi, address={bus=0x00, domain=0x0000, slot=0x04, type=pci, function=0x0}, specParams={}, device=scsi, type=controller, deviceId=fc27e446-7932-40e4-98bd-2d13237ed6f5}],acpiEnable=true,cpuShares=1024,vmName=PRTG,cpuType=Conroe,custom={device_ac3c9c1c-9d8d-4ced-ba59-977f54ccb9eedevice_804006d1-ed61-4c0e-9818-0d0f4f0e8e3cdevice_b6ac752a-13e2-4107-aa8e-ddc054551f15=VmDevice {vmId=92fbccc5-1c99-4020-822b-74d43ad214c3, deviceId=b6ac752a-13e2-4107-aa8e-ddc054551f15, 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_ac3c9c1c-9d8d-4ced-ba59-977f54ccb9eedevice_804006d1-ed61-4c0e-9818-0d0f4f0e8e3cdevice_b6ac752a-13e2-4107-aa8e-ddc054551f15device_83ffb451-8ba0-4b56-8082-b243b793d83e=VmDevice {vmId=92fbccc5-1c99-4020-822b-74d43ad214c3, deviceId=83ffb451-8ba0-4b56-8082-b243b793d83e, 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}, device_ac3c9c1c-9d8d-4ced-ba59-977f54ccb9eedevice_804006d1-ed61-4c0e-9818-0d0f4f0e8e3cdevice_b6ac752a-13e2-4107-aa8e-ddc054551f15device_83ffb451-8ba0-4b56-8082-b243b793d83edevice_f8e59a5e-20a3-4a45-91bf-804ad60f9efb=VmDevice {vmId=92fbccc5-1c99-4020-822b-74d43ad214c3, deviceId=f8e59a5e-20a3-4a45-91bf-804ad60f9efb, 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_ac3c9c1c-9d8d-4ced-ba59-977f54ccb9ee=VmDevice {vmId=92fbccc5-1c99-4020-822b-74d43ad214c3, deviceId=ac3c9c1c-9d8d-4ced-ba59-977f54ccb9ee, 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_ac3c9c1c-9d8d-4ced-ba59-977f54ccb9eedevice_804006d1-ed61-4c0e-9818-0d0f4f0e8e3c=VmDevice {vmId=92fbccc5-1c99-4020-822b-74d43ad214c3, deviceId=804006d1-ed61-4c0e-9818-0d0f4f0e8e3c, device=virtio-serial, type=CONTROLLER, bootOrder=0, specParams={}, address={bus=0x00, domain=0x0000, type=pci, slot=0x05, function=0x0}, managed=false, plugged=true, readOnly=false, deviceAlias=virtio-serial0, customProperties={}, snapshotId=null}} 2014-03-31 13:53:54,971 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] (org.ovirt.thread.pool-6-thread-4) [787f133c] FINISH, CreateVDSCommand, log id: 7b64d5f2 2014-03-31 13:53:54,982 INFO [org.ovirt.engine.core.vdsbroker.CreateVmVDSCommand] (org.ovirt.thread.pool-6-thread-4) [787f133c] FINISH, CreateVmVDSCommand, return: WaitForLaunch, log id: 497b9920 2014-03-31 13:53:54,986 INFO [org.ovirt.engine.core.bll.RunVmCommand] (org.ovirt.thread.pool-6-thread-4) [787f133c] Lock freed to object EngineLock [exclusiveLocks= key: 92fbccc5-1c99-4020-822b-74d43ad214c3 value: VM , sharedLocks= ] 2014-03-31 13:53:54,995 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-6-thread-4) [787f133c] Correlation ID: 787f133c, Job ID: e9bc3c5d-a16f-4cfc-ae35-340d153893b9, Call Stack: null, Custom Event ID: -1, Message: VM PRTG was started by admin (Host: virtual6). 2014-03-31 13:53:55,232 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (DefaultQuartzScheduler_Worker-15) START, DestroyVDSCommand(HostName = virtual6, HostId = e11c37b0-d79d-417b-bd6f-6dc172f7921c, vmId=92fbccc5-1c99-4020-822b-74d43ad214c3, force=false, secondsToWait=0, gracefully=false), log id: 780a285e 2014-03-31 13:53:55,252 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (DefaultQuartzScheduler_Worker-15) FINISH, DestroyVDSCommand, log id: 780a285e 2014-03-31 13:53:55,315 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (org.ovirt.thread.pool-6-thread-22) Domain b157f887-ae9a-4337-8c55-7c8a9df017bb:imagini recovered from problem. vds: virtual5 2014-03-31 13:53:55,319 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (org.ovirt.thread.pool-6-thread-22) Domain 62f795ed-486c-443d-93e9-2c16595fe546:masini recovered from problem. vds: virtual5 2014-03-31 13:53:55,342 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (DefaultQuartzScheduler_Worker-15) Correlation ID: null, Call Stack: null, Custom Event ID: -1, Message: VM PRTG is down. Exit message: 'int' object has no attribute 'replace'. 2014-03-31 13:53:55,346 INFO [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (DefaultQuartzScheduler_Worker-15) Running on vds during rerun failed vm: null 2014-03-31 13:53:55,351 INFO [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (DefaultQuartzScheduler_Worker-15) VM PRTG (92fbccc5-1c99-4020-822b-74d43ad214c3) is running in db and not running in VDS virtual6 2014-03-31 13:53:55,355 INFO [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (DefaultQuartzScheduler_Worker-15) add VM PRTG to HA rerun treatment 2014-03-31 13:53:55,366 ERROR [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (DefaultQuartzScheduler_Worker-15) Rerun vm 92fbccc5-1c99-4020-822b-74d43ad214c3. Called from vds virtual6 2014-03-31 13:53:55,375 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-6-thread-25) Correlation ID: 787f133c, Job ID: e9bc3c5d-a16f-4cfc-ae35-340d153893b9, Call Stack: null, Custom Event ID: -1, Message: Failed to run VM PRTG on Host virtual6. 2014-03-31 13:53:55,399 INFO [org.ovirt.engine.core.bll.RunVmCommand] (org.ovirt.thread.pool-6-thread-25) Lock Acquired to object EngineLock [exclusiveLocks= key: 92fbccc5-1c99-4020-822b-74d43ad214c3 value: VM , sharedLocks= ] 2014-03-31 13:53:55,424 INFO [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (org.ovirt.thread.pool-6-thread-25) START, IsVmDuringInitiatingVDSCommand( vmId = 92fbccc5-1c99-4020-822b-74d43ad214c3), log id: 80df73c 2014-03-31 13:53:55,429 INFO [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (org.ovirt.thread.pool-6-thread-25) FINISH, IsVmDuringInitiatingVDSCommand, return: false, log id: 80df73c 2014-03-31 13:53:55,458 INFO [org.ovirt.engine.core.bll.RunVmCommand] (org.ovirt.thread.pool-6-thread-25) Running command: RunVmCommand internal: false. Entities affected : ID: 92fbccc5-1c99-4020-822b-74d43ad214c3 Type: VM 2014-03-31 13:53:55,464 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (org.ovirt.thread.pool-6-thread-21) Domain b157f887-ae9a-4337-8c55-7c8a9df017bb:imagini recovered from problem. vds: virtual4 2014-03-31 13:53:55,482 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (org.ovirt.thread.pool-6-thread-21) Domain 62f795ed-486c-443d-93e9-2c16595fe546:masini recovered from problem. vds: virtual4 2014-03-31 13:53:55,534 INFO [org.ovirt.engine.core.bll.scheduling.policyunits.HaReservationWeightPolicyUnit] (org.ovirt.thread.pool-6-thread-25) Started HA reservation scoring method 2014-03-31 13:53:55,551 INFO [org.ovirt.engine.core.vdsbroker.CreateVmVDSCommand] (org.ovirt.thread.pool-6-thread-25) START, CreateVmVDSCommand(HostName = virtual5, HostId = ee8c0f32-5129-48ec-b024-8ae83d5835eb, vmId=92fbccc5-1c99-4020-822b-74d43ad214c3, vm=VM [PRTG]), log id: 5db07e26 2014-03-31 13:53:55,561 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] (org.ovirt.thread.pool-6-thread-25) START, CreateVDSCommand(HostName = virtual5, HostId = ee8c0f32-5129-48ec-b024-8ae83d5835eb, vmId=92fbccc5-1c99-4020-822b-74d43ad214c3, vm=VM [PRTG]), log id: 41f8abfd 2014-03-31 13:53:55,624 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] (org.ovirt.thread.pool-6-thread-25) org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand spiceSslCipherSuite=DEFAULT,memSize=2048,kvmEnable=true,smp=1,vmType=kvm,emulatedMachine=pc-1.0,keyboardLayout=en-us,memGuaranteedSize=1365,nice=0,display=qxl,smartcardEnable=false,smpCoresPerSocket=1,spiceSecureChannels=smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard,timeOffset=3600,transparentHugePages=true,vmId=92fbccc5-1c99-4020-822b-74d43ad214c3,devices=[{address={bus=0x00, domain=0x0000, slot=0x02, type=pci, function=0x0}, specParams={vram=32768, heads=1}, device=qxl, type=video, deviceId=e46018f8-fbfc-484d-891a-e7ade9f88c51}, {shared=false, bootOrder=2, iface=ide, index=2, address={unit=0, bus=1, target=0, controller=0, type=drive}, specParams={path=}, path=, device=cdrom, type=disk, readonly=true, deviceId=8eac07a3-d353-43db-b2e3-5f8fe414bdfe}, {shared=false, index=0, volumeID=438299fb-0a72-4005-b0c8-5544eece6dba, propagateErrors=off, format=raw, type=disk, iface=virtio, bootOrder=1, address={bus=0x00, domain=0x0000, slot=0x06, type=pci, function=0x0}, domainID=041e8dbe-f405-4aca-bb78-3bf3cc7dc190, imageID=68051a25-d3de-46b4-9e4b-686d824146bf, specParams={}, optional=false, device=disk, poolID=5849b030-626e-47cb-ad90-3ce782d831b3, readonly=false, deviceId=68051a25-d3de-46b4-9e4b-686d824146bf}, {nicModel=pv, address={bus=0x00, domain=0x0000, slot=0x03, type=pci, function=0x0}, specParams={outbound={peak=26880, burst=256000, average=25600}, inbound={peak=26880, burst=256000, average=25600}}, macAddr=00:1a:4a:69:90:de, device=bridge, linkActive=true, type=interface, filter=vdsm-no-mac-spoofing, network=VPO_IPPROXY, deviceId=553de5f6-e108-4c45-84d2-7a292304211f}, {specParams={model=virtio}, device=memballoon, type=balloon, deviceId=68c759aa-6266-432c-9b8b-7a4b215eee57}, {index=0, model=virtio-scsi, address={bus=0x00, domain=0x0000, slot=0x04, type=pci, function=0x0}, specParams={}, device=scsi, type=controller, deviceId=fc27e446-7932-40e4-98bd-2d13237ed6f5}],acpiEnable=true,cpuShares=1024,vmName=PRTG,cpuType=Conroe,custom={device_ac3c9c1c-9d8d-4ced-ba59-977f54ccb9eedevice_804006d1-ed61-4c0e-9818-0d0f4f0e8e3cdevice_b6ac752a-13e2-4107-aa8e-ddc054551f15=VmDevice {vmId=92fbccc5-1c99-4020-822b-74d43ad214c3, deviceId=b6ac752a-13e2-4107-aa8e-ddc054551f15, 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_ac3c9c1c-9d8d-4ced-ba59-977f54ccb9eedevice_804006d1-ed61-4c0e-9818-0d0f4f0e8e3cdevice_b6ac752a-13e2-4107-aa8e-ddc054551f15device_83ffb451-8ba0-4b56-8082-b243b793d83e=VmDevice {vmId=92fbccc5-1c99-4020-822b-74d43ad214c3, deviceId=83ffb451-8ba0-4b56-8082-b243b793d83e, 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}, device_ac3c9c1c-9d8d-4ced-ba59-977f54ccb9eedevice_804006d1-ed61-4c0e-9818-0d0f4f0e8e3cdevice_b6ac752a-13e2-4107-aa8e-ddc054551f15device_83ffb451-8ba0-4b56-8082-b243b793d83edevice_f8e59a5e-20a3-4a45-91bf-804ad60f9efb=VmDevice {vmId=92fbccc5-1c99-4020-822b-74d43ad214c3, deviceId=f8e59a5e-20a3-4a45-91bf-804ad60f9efb, 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_ac3c9c1c-9d8d-4ced-ba59-977f54ccb9ee=VmDevice {vmId=92fbccc5-1c99-4020-822b-74d43ad214c3, deviceId=ac3c9c1c-9d8d-4ced-ba59-977f54ccb9ee, 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_ac3c9c1c-9d8d-4ced-ba59-977f54ccb9eedevice_804006d1-ed61-4c0e-9818-0d0f4f0e8e3c=VmDevice {vmId=92fbccc5-1c99-4020-822b-74d43ad214c3, deviceId=804006d1-ed61-4c0e-9818-0d0f4f0e8e3c, device=virtio-serial, type=CONTROLLER, bootOrder=0, specParams={}, address={bus=0x00, domain=0x0000, type=pci, slot=0x05, function=0x0}, managed=false, plugged=true, readOnly=false, deviceAlias=virtio-serial0, customProperties={}, snapshotId=null}} 2014-03-31 13:53:55,675 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] (org.ovirt.thread.pool-6-thread-25) FINISH, CreateVDSCommand, log id: 41f8abfd 2014-03-31 13:53:55,683 INFO [org.ovirt.engine.core.vdsbroker.CreateVmVDSCommand] (org.ovirt.thread.pool-6-thread-25) FINISH, CreateVmVDSCommand, return: WaitForLaunch, log id: 5db07e26 2014-03-31 13:53:55,685 INFO [org.ovirt.engine.core.bll.RunVmCommand] (org.ovirt.thread.pool-6-thread-25) Lock freed to object EngineLock [exclusiveLocks= key: 92fbccc5-1c99-4020-822b-74d43ad214c3 value: VM , sharedLocks= ] 2014-03-31 13:53:55,692 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-6-thread-25) Correlation ID: 787f133c, Job ID: e9bc3c5d-a16f-4cfc-ae35-340d153893b9, Call Stack: null, Custom Event ID: -1, Message: VM PRTG was started by admin (Host: virtual5). 2014-03-31 13:53:58,350 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (DefaultQuartzScheduler_Worker-25) START, DestroyVDSCommand(HostName = virtual5, HostId = ee8c0f32-5129-48ec-b024-8ae83d5835eb, vmId=92fbccc5-1c99-4020-822b-74d43ad214c3, force=false, secondsToWait=0, gracefully=false), log id: 49a8c278 2014-03-31 13:53:58,370 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (DefaultQuartzScheduler_Worker-25) FINISH, DestroyVDSCommand, log id: 49a8c278 2014-03-31 13:53:58,433 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (org.ovirt.thread.pool-6-thread-36) Domain b157f887-ae9a-4337-8c55-7c8a9df017bb:imagini recovered from problem. vds: virtual6 2014-03-31 13:53:58,436 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (org.ovirt.thread.pool-6-thread-36) Domain b157f887-ae9a-4337-8c55-7c8a9df017bb:imagini has recovered from problem. No active host in the DC is reporting it as problematic, so clearing the domain recovery timer. 2014-03-31 13:53:58,445 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (org.ovirt.thread.pool-6-thread-36) Domain 62f795ed-486c-443d-93e9-2c16595fe546:masini recovered from problem. vds: virtual6 2014-03-31 13:53:58,450 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (org.ovirt.thread.pool-6-thread-36) Domain 62f795ed-486c-443d-93e9-2c16595fe546:masini has recovered from problem. No active host in the DC is reporting it as problematic, so clearing the domain recovery timer. 2014-03-31 13:53:58,454 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (DefaultQuartzScheduler_Worker-25) Correlation ID: null, Call Stack: null, Custom Event ID: -1, Message: VM PRTG is down. Exit message: 'int' object has no attribute 'replace'. 2014-03-31 13:53:58,460 INFO [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (DefaultQuartzScheduler_Worker-25) Running on vds during rerun failed vm: null 2014-03-31 13:53:58,463 INFO [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (DefaultQuartzScheduler_Worker-25) VM PRTG (92fbccc5-1c99-4020-822b-74d43ad214c3) is running in db and not running in VDS virtual5 2014-03-31 13:53:58,466 INFO [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (DefaultQuartzScheduler_Worker-25) add VM PRTG to HA rerun treatment 2014-03-31 13:53:58,475 ERROR [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (DefaultQuartzScheduler_Worker-25) Rerun vm 92fbccc5-1c99-4020-822b-74d43ad214c3. Called from vds virtual5 2014-03-31 13:53:58,482 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-6-thread-19) Correlation ID: 787f133c, Job ID: e9bc3c5d-a16f-4cfc-ae35-340d153893b9, Call Stack: null, Custom Event ID: -1, Message: Failed to run VM PRTG on Host virtual5. 2014-03-31 13:53:58,501 INFO [org.ovirt.engine.core.bll.RunVmCommand] (org.ovirt.thread.pool-6-thread-19) Lock Acquired to object EngineLock [exclusiveLocks= key: 92fbccc5-1c99-4020-822b-74d43ad214c3 value: VM , sharedLocks= ] 2014-03-31 13:53:58,526 INFO [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (org.ovirt.thread.pool-6-thread-19) START, IsVmDuringInitiatingVDSCommand( vmId = 92fbccc5-1c99-4020-822b-74d43ad214c3), log id: 2b5bee5b 2014-03-31 13:53:58,532 INFO [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (org.ovirt.thread.pool-6-thread-19) FINISH, IsVmDuringInitiatingVDSCommand, return: false, log id: 2b5bee5b 2014-03-31 13:53:58,556 INFO [org.ovirt.engine.core.bll.RunVmCommand] (org.ovirt.thread.pool-6-thread-19) Running command: RunVmCommand internal: false. Entities affected : ID: 92fbccc5-1c99-4020-822b-74d43ad214c3 Type: VM 2014-03-31 13:53:58,589 INFO [org.ovirt.engine.core.vdsbroker.CreateVmVDSCommand] (org.ovirt.thread.pool-6-thread-19) START, CreateVmVDSCommand(HostName = virtual4, HostId = f4fc34ed-4261-46f1-ac5e-c849eb7e9b7a, vmId=92fbccc5-1c99-4020-822b-74d43ad214c3, vm=VM [PRTG]), log id: 5bfb709 2014-03-31 13:53:58,596 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] (org.ovirt.thread.pool-6-thread-19) START, CreateVDSCommand(HostName = virtual4, HostId = f4fc34ed-4261-46f1-ac5e-c849eb7e9b7a, vmId=92fbccc5-1c99-4020-822b-74d43ad214c3, vm=VM [PRTG]), log id: 2fa9cbb3 2014-03-31 13:53:58,887 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] (org.ovirt.thread.pool-6-thread-19) org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand spiceSslCipherSuite=DEFAULT,memSize=2048,kvmEnable=true,smp=1,vmType=kvm,emulatedMachine=pc-1.0,keyboardLayout=en-us,memGuaranteedSize=1365,nice=0,display=qxl,smartcardEnable=false,smpCoresPerSocket=1,spiceSecureChannels=smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard,timeOffset=3600,transparentHugePages=true,vmId=92fbccc5-1c99-4020-822b-74d43ad214c3,devices=[{address={bus=0x00, domain=0x0000, slot=0x02, type=pci, function=0x0}, specParams={vram=32768, heads=1}, device=qxl, type=video, deviceId=e46018f8-fbfc-484d-891a-e7ade9f88c51}, {shared=false, bootOrder=2, iface=ide, index=2, address={unit=0, bus=1, target=0, controller=0, type=drive}, specParams={path=}, path=, device=cdrom, type=disk, readonly=true, deviceId=8eac07a3-d353-43db-b2e3-5f8fe414bdfe}, {shared=false, index=0, volumeID=438299fb-0a72-4005-b0c8-5544eece6dba, propagateErrors=off, format=raw, type=disk, iface=virtio, bootOrder=1, address={bus=0x00, domain=0x0000, slot=0x06, type=pci, function=0x0}, domainID=041e8dbe-f405-4aca-bb78-3bf3cc7dc190, imageID=68051a25-d3de-46b4-9e4b-686d824146bf, specParams={}, optional=false, device=disk, poolID=5849b030-626e-47cb-ad90-3ce782d831b3, readonly=false, deviceId=68051a25-d3de-46b4-9e4b-686d824146bf}, {nicModel=pv, address={bus=0x00, domain=0x0000, slot=0x03, type=pci, function=0x0}, specParams={outbound={peak=26880, burst=256000, average=25600}, inbound={peak=26880, burst=256000, average=25600}}, macAddr=00:1a:4a:69:90:de, device=bridge, linkActive=true, type=interface, filter=vdsm-no-mac-spoofing, network=VPO_IPPROXY, deviceId=553de5f6-e108-4c45-84d2-7a292304211f}, {specParams={model=virtio}, device=memballoon, type=balloon, deviceId=68c759aa-6266-432c-9b8b-7a4b215eee57}, {index=0, model=virtio-scsi, address={bus=0x00, domain=0x0000, slot=0x04, type=pci, function=0x0}, specParams={}, device=scsi, type=controller, deviceId=fc27e446-7932-40e4-98bd-2d13237ed6f5}],acpiEnable=true,cpuShares=1024,vmName=PRTG,cpuType=Conroe,custom={device_ac3c9c1c-9d8d-4ced-ba59-977f54ccb9eedevice_804006d1-ed61-4c0e-9818-0d0f4f0e8e3cdevice_b6ac752a-13e2-4107-aa8e-ddc054551f15=VmDevice {vmId=92fbccc5-1c99-4020-822b-74d43ad214c3, deviceId=b6ac752a-13e2-4107-aa8e-ddc054551f15, 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_ac3c9c1c-9d8d-4ced-ba59-977f54ccb9eedevice_804006d1-ed61-4c0e-9818-0d0f4f0e8e3cdevice_b6ac752a-13e2-4107-aa8e-ddc054551f15device_83ffb451-8ba0-4b56-8082-b243b793d83e=VmDevice {vmId=92fbccc5-1c99-4020-822b-74d43ad214c3, deviceId=83ffb451-8ba0-4b56-8082-b243b793d83e, 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}, device_ac3c9c1c-9d8d-4ced-ba59-977f54ccb9eedevice_804006d1-ed61-4c0e-9818-0d0f4f0e8e3cdevice_b6ac752a-13e2-4107-aa8e-ddc054551f15device_83ffb451-8ba0-4b56-8082-b243b793d83edevice_f8e59a5e-20a3-4a45-91bf-804ad60f9efb=VmDevice {vmId=92fbccc5-1c99-4020-822b-74d43ad214c3, deviceId=f8e59a5e-20a3-4a45-91bf-804ad60f9efb, 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_ac3c9c1c-9d8d-4ced-ba59-977f54ccb9ee=VmDevice {vmId=92fbccc5-1c99-4020-822b-74d43ad214c3, deviceId=ac3c9c1c-9d8d-4ced-ba59-977f54ccb9ee, 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_ac3c9c1c-9d8d-4ced-ba59-977f54ccb9eedevice_804006d1-ed61-4c0e-9818-0d0f4f0e8e3c=VmDevice {vmId=92fbccc5-1c99-4020-822b-74d43ad214c3, deviceId=804006d1-ed61-4c0e-9818-0d0f4f0e8e3c, device=virtio-serial, type=CONTROLLER, bootOrder=0, specParams={}, address={bus=0x00, domain=0x0000, type=pci, slot=0x05, function=0x0}, managed=false, plugged=true, readOnly=false, deviceAlias=virtio-serial0, customProperties={}, snapshotId=null}} 2014-03-31 13:53:58,936 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] (org.ovirt.thread.pool-6-thread-19) FINISH, CreateVDSCommand, log id: 2fa9cbb3 2014-03-31 13:53:58,943 INFO [org.ovirt.engine.core.vdsbroker.CreateVmVDSCommand] (org.ovirt.thread.pool-6-thread-19) FINISH, CreateVmVDSCommand, return: WaitForLaunch, log id: 5bfb709 2014-03-31 13:53:58,946 INFO [org.ovirt.engine.core.bll.RunVmCommand] (org.ovirt.thread.pool-6-thread-19) Lock freed to object EngineLock [exclusiveLocks= key: 92fbccc5-1c99-4020-822b-74d43ad214c3 value: VM , sharedLocks= ] 2014-03-31 13:53:58,952 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-6-thread-19) Correlation ID: 787f133c, Job ID: e9bc3c5d-a16f-4cfc-ae35-340d153893b9, Call Stack: null, Custom Event ID: -1, Message: VM PRTG was started by admin (Host: virtual4). 2014-03-31 13:53:59,142 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-26) START, GlusterVolumesListVDSCommand(HostName = virtual6, HostId = e11c37b0-d79d-417b-bd6f-6dc172f7921c), log id: 45331b03 2014-03-31 13:53:59,186 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-26) FINISH, GlusterVolumesListVDSCommand, return: {3eb2a0de-c6f7-4ef8-a9fd-777d9e529adc=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@7ab347f8, a297bf18-e147-4792-b590-1f485732f8ee=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@237e1375}, log id: 45331b03 2014-03-31 13:54:01,519 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (DefaultQuartzScheduler_Worker-32) START, DestroyVDSCommand(HostName = virtual4, HostId = f4fc34ed-4261-46f1-ac5e-c849eb7e9b7a, vmId=92fbccc5-1c99-4020-822b-74d43ad214c3, force=false, secondsToWait=0, gracefully=false), log id: 27d3bc97 2014-03-31 13:54:01,540 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (DefaultQuartzScheduler_Worker-32) FINISH, DestroyVDSCommand, log id: 27d3bc97 2014-03-31 13:54:01,561 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (DefaultQuartzScheduler_Worker-32) Correlation ID: null, Call Stack: null, Custom Event ID: -1, Message: VM PRTG is down. Exit message: 'int' object has no attribute 'replace'. 2014-03-31 13:54:01,565 INFO [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (DefaultQuartzScheduler_Worker-32) Running on vds during rerun failed vm: null 2014-03-31 13:54:01,568 INFO [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (DefaultQuartzScheduler_Worker-32) VM PRTG (92fbccc5-1c99-4020-822b-74d43ad214c3) is running in db and not running in VDS virtual4 2014-03-31 13:54:01,571 INFO [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (DefaultQuartzScheduler_Worker-32) add VM PRTG to HA rerun treatment 2014-03-31 13:54:01,579 ERROR [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (DefaultQuartzScheduler_Worker-32) Rerun vm 92fbccc5-1c99-4020-822b-74d43ad214c3. Called from vds virtual4 2014-03-31 13:54:01,587 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-6-thread-14) Correlation ID: 787f133c, Job ID: e9bc3c5d-a16f-4cfc-ae35-340d153893b9, Call Stack: null, Custom Event ID: -1, Message: Failed to run VM PRTG on Host virtual4. 2014-03-31 13:54:01,605 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-6-thread-14) Correlation ID: 787f133c, Job ID: e9bc3c5d-a16f-4cfc-ae35-340d153893b9, Call Stack: null, Custom Event ID: -1, Message: Failed to run VM PRTG (User: admin). On Mon, Mar 31, 2014 at 1:47 PM, Dan Kenigsberg <danken(a)redhat.com&gt; wrote:

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:

Hello! Do I have enable kvm and libvirt also on engine? I think not "*Note:* On Fedora 19, you'll need to enable fedora-virt-preview repository for using Fedora 19 as node on 3.4 cluster" .....the problem still persist On Mon, Mar 31, 2014 at 2:34 PM, Joop <jvdwege(a)xs4all.nl&gt; wrote:

Hi, ----- Original Message ----- You've very likely experienced the same problem reported here https://bugzilla.redhat.com/show_bug.cgi?id=1067064 A fix was already been committed. About kvm and libvirt, you only need them on the nodes running hypervisors; engine itself does not depend on them. -- Francesco Romani RedHat Engineering Virtualization R & D Phone: 8261328 IRC: fromani

On Mon, Mar 31, 2014 at 04:57:44PM +0300, Gabi C wrote: No, thank you for reporting this. The patch still awaits verification http://gerrit.ovirt.org/#/c/26254/ I would very much appreciate if you can apply it on your host's vdsm, re-add the QoS profiles, and report if life is good again. Dan.

On Wed, Apr 02, 2014 at 10:06:00AM +0300, Gabi C wrote: The patch has now been merged, and would get into the next release of Vdsm (most probably not before ovirt-3.4.1)