- Users - oVirt List Archives

[Users] ovirt-cli 3.2.0.3 - important changes
by Michael Pasternak 20 Sep '12

20 Sep '12

Two commands renamed: -------------------- - "create" command renamed with "add" #855773. - "delete" command renamed with "remove" #855769. Changed authentication procedure: -------------------------------- - added username/password prompt/conf-file functionality (see [1] for more details). [1] http://wiki.ovirt.org/wiki/CLI#Connect * For complete list of changes, see change log. -- Michael Pasternak RedHat, ENG-Virtualization R&D

1 0

[Users] where do bond interfaces come from when adding a node that is FC17
by Christopher Maestas 20 Sep '12

20 Sep '12

When you add a fc17 node and look at it, it seems to add: * ovirtmgmt bridge * p2p1 interface * and bond0-bond3. Where does the bonding information get stored? It doesn't seem to be in /etc/sysconfig/network-scripts? The reason I ask, is I have two nodes one of which has the bonding interfaces up and the other which doesn't. The one that doesn't have the bonding interfaces up is failing to be added to the ovirt node list. Thanks, -cdm

4 3

[Users] Host migration problem
by Dmitriy A Pyryakov 20 Sep '12

20 Sep '12

--0__=C9BBF0ECDFB7B2218f9e8a93df938690918cC9BBF0ECDFB7B221 Content-type: text/plain; charset=US-ASCII Content-transfer-encoding: quoted-printable Hello, Yesturday I broke my two Fedora 17 hosts. Today I install two ovirt nodes (first - 2.5.0-2.0.fc17, second - 2.5.1-1.0.fc17). SPM on 2.5.0-2.0.fc17. Now, I can't run any of my existing virtual machines. Exit message: unsupported configuration: spice secure channels set in XML configurati= on, but TLS is disabled in qemu.conf. engine.log: [root@admin ~]# tail -f -n 0 /var/log/ovirt-engine/engine.log 2012-09-20 12:42:53,289 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand] (ajp--0.0.0.0-8009-10) START, IsValidVDSCommand(storagePoolId =3D 332694bb-364a-434e-b23f-5fef985d3cbd, ignoreFailoverLimit =3D false, compatabilityVersion =3D null), log id: 7c90c641 2012-09-20 12:42:53,294 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand] (ajp--0.0.0.0-8009-10) FINISH, IsValidVDSCommand, return: true, log id:= 7c90c641 2012-09-20 12:42:53,332 INFO [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (ajp--0.0.0.0-8009-10) START, IsVmDuringInitiatingVDSCommand(vmId =3D 509e608c-e657-473a-b031-f0811da96bde), log id: 243c74f7 2012-09-20 12:42:53,334 INFO [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (ajp--0.0.0.0-8009-10) FINISH, IsVmDuringInitiatingVDSCommand, return: false, log id: 243c74f7 2012-09-20 12:42:53,403 INFO [org.ovirt.engine.core.bll.RunVmCommand] (pool-3-thread-50) [a58d974] Lock Acquired to object EngineLock [exclusiveLocks=3D key: 509e608c-e657-473a-b031-f0811da96bde value: VM , sharedLocks=3D ] 2012-09-20 12:42:53,415 INFO [org.ovirt.engine.core.bll.RunVmCommand] (pool-3-thread-50) [a58d974] Running command: RunVmCommand internal: fa= lse. Entities affected : ID: 509e608c-e657-473a-b031-f0811da96bde Type: VM 2012-09-20 12:42:53,504 INFO [org.ovirt.engine.core.vdsbroker.CreateVmVDSCommand] (pool-3-thread-50)= [a58d974] START, CreateVmVDSCommand(vdsId =3D 0a268762-02d7-11e2-b750-0011856cf23e, vmId=3D509e608c-e657-473a-b031-f0811da96bde, vm=3Dorg.ovirt.engine.core.common.businessentities.VM@1911737b), log id= : 77c0e559 2012-09-20 12:42:53,529 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] (pool-3-thread-50) [a58d974] START, CreateVDSCommand(vdsId =3D 0a268762-02d7-11e2-b750-0011856cf23e, vmId=3D509e608c-e657-473a-b031-f0811da96bde, vm=3Dorg.ovirt.engine.core.common.businessentities.VM@1911737b), log id= : f48008f 2012-09-20 12:42:53,602 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] (pool-3-thread-50) [a58d974] org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand spiceSslCipherSuite=3DDEFAULT,memSize=3D1024,kvmEnable=3Dtrue,smp=3D1,e= mulatedMachine=3Dpc-0.14,vmType=3Dkvm,keyboardLayout=3Den-us,pitReinjec= tion=3Dfalse,nice=3D0,display=3Dqxl,smpCoresPerSocket=3D1,spiceSecureCh= annels=3Dsmain,sinputs,scursor,splayback,srecord,sdisplay,displayNetwor= k=3Dovirtmgmt,timeOffset=3D-1,transparentHugePages=3Dtrue,vmId=3D509e60= 8c -e657-473a-b031-f0811da96bde,devices=3D [Ljava.util.Map;@760db68c,acpiEnable=3Dtrue,vmName=3DCentOS6Thames,cpuT= ype=3DConroe,custom=3D {device_bb912edd-9790-43ff-a758-f1d9f20cb5f5device_f5c86859-5ae9-4a37-9= d34-2b9547609622device_20a11f26-6a39-415d-a7bf-95893b9c55b5=3DVmId=3D50= 9e608c-e657-473a-b031-f0811da96bde,DeviceId=3D20a11f26-6a39-415d-a7bf-9= 5893b9c55b5,Device=3Dunix,Type=3Dchannel,BootOrder=3D0,SpecParams=3D {},Address=3D{port=3D1, bus=3D0, controller=3D0, type=3Dvirtio-serial},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3Df= alse,alias=3D channel0, device_bb912edd-9790-43ff-a758-f1d9f20cb5f5=3DVmId=3D509e608c-e657-473a= -b031-f0811da96bde,DeviceId=3Dbb912edd-9790-43ff-a758-f1d9f20cb5f5,Devi= ce=3Dide,Type=3Dcontroller,BootOrder=3D0,SpecParams=3D {},Address=3D{bus=3D0x00, domain=3D0x0000, type=3Dpci, slot=3D0x01, function=3D0x1},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3Dfalse,a= lias=3Dide0, device_bb912edd-9790-43ff-a758-f1d9f20cb5f5device_f5c86859-5ae9-4a37-9d= 34-2b9547609622=3DVmId=3D509e608c-e657-473a-b031-f0811da96bde,DeviceId=3D= f5c86859-5ae9-4a37-9d34-2b9547609622,Devic e=3Dvirtio-serial,Type=3Dcontroller,BootOrder=3D0,SpecParams=3D{},Addre= ss=3D {bus=3D0x00, domain=3D0x0000, type=3Dpci, slot=3D0x04, function=3D0x0},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3Dfalse,a= lias=3Dvirtio-serial0, device_bb912edd-9790-43ff-a758-f1d9f20cb5f5device_f5c86859-5ae9-4a37-9d= 34-2b9547609622device_20a11f26-6a39-415d-a7bf-95893b9c55b5device_21f255= dc-9b3b-48d8-b8e4-63c1635e269b=3DVmId=3D509e608c-e657-473a-b031-f0811da= 96bde,DeviceId=3D21f255dc-9b3b-48d8-b8e4-63c1635e269b,Device=3Dspicevmc= ,Type=3Dchannel,BootOrder=3D0,SpecP arams=3D{},Address=3D{port=3D2, bus=3D0, co= ntroller=3D0, type=3Dvirtio-serial},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3Df= alse,alias=3Dchannel1, device_bb912edd-9790-43ff-a758-f1d9f20cb5f5device_f5c86859-5ae9-4a37-9d= 34-2b9547609622device_20a11f26-6a39-415d-a7bf-95893b9c55b5device_21f255= dc-9b3b-48d8-b8e4-63c1635e269bdevice_d6c2c4d1-da6b-44fe-a5aa-508135c7fd= fe=3DVmId=3D509e608c-e657-473a-b031-f0811da96bde,DeviceId=3Dd6c2c4d1-da= 6b-44fe-a5aa-508135c7fdfe,Device=3Dusb,Type=3Dcontroller,BootOrder=3D0,= SpecParams=3D {},Address=3D{bus=3D0x0 0, domain=3D0x0000, = type=3Dpci, slot=3D0x01, function=3D0x2},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3Dfalse,a= lias=3Dusb0} 2012-09-20 12:42:53,625 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] (pool-3-thread-50) [a58d974] FINISH, CreateVDSCommand, log id: f48008f 2012-09-20 12:42:53,659 INFO [org.ovirt.engine.core.vdsbroker.CreateVmVDSCommand] (pool-3-thread-50)= [a58d974] IncreasePendingVms::CreateVmIncreasing vds hyper1.ovirt.com pending vcpu count, now 1. Vm: CentOS6Thames 2012-09-20 12:42:53,671 INFO [org.ovirt.engine.core.vdsbroker.CreateVmVDSCommand] (pool-3-thread-50)= [a58d974] FINISH, CreateVmVDSCommand, return: WaitForLaunch, log id: 77c0e559 2012-09-20 12:42:53,684 INFO [org.ovirt.engine.core.bll.RunVmCommand] (pool-3-thread-50) [a58d974] Lock freed to object EngineLock [exclusiveLocks=3D key: 509e608c-e657-473a-b031-f0811da96bde value: VM , sharedLocks=3D ] 2012-09-20 12:42:54,418 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (QuartzScheduler_Worker-12) START, DestroyVDSCommand(vdsId =3D 0a268762-02d7-11e2-b750-0011856cf23e, vmId=3D509e608c-e657-473a-b031-f0811da96bde, force=3Dfalse, secondsToWa= it=3D0, gracefully=3Dfalse), log id: 2f059be9 2012-09-20 12:42:54,486 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (QuartzScheduler_Worker-12) FINISH, DestroyVDSCommand, log id: 2f059be9= 2012-09-20 12:42:54,520 INFO [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Worker-12) Running on vds during rerun failed vm: null= 2012-09-20 12:42:54,523 INFO [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Worker-12) vm CentOS6Thames running in db and not runn= ing in vds - add to rerun treatment. vds hyper1.ovirt.com 2012-09-20 12:42:54,536 ERROR [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Worker-12) Rerun vm 509e608c-e657-473a-b031-f0811da96b= de. Called from vds hyper1.ovirt.com 2012-09-20 12:42:54,557 INFO [org.ovirt.engine.core.vdsbroker.UpdateVdsDynamicDataVDSCommand] (pool-3-thread-50) START, UpdateVdsDynamicDataVDSCommand(vdsId =3D 0a268762-02d7-11e2-b750-0011856cf23e, vdsDynamic=3Dorg.ovirt.engine.core.common.businessentities.VdsDynamic@d= b702e05), log id: 71c6e6a3 2012-09-20 12:42:54,564 INFO [org.ovirt.engine.core.vdsbroker.UpdateVdsDynamicDataVDSCommand] (pool-3-thread-50) FINISH, UpdateVdsDynamicDataVDSCommand, log id: 71c6= e6a3 2012-09-20 12:42:54,584 INFO [org.ovirt.engine.core.bll.RunVmCommand] (pool-3-thread-50) Lock Acquired to object EngineLock [exclusiveLocks=3D= key: 509e608c-e657-473a-b031-f0811da96bde value: VM , sharedLocks=3D ] 2012-09-20 12:42:54,603 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand] (pool-3-thread-50) START, IsValidVDSCommand(storagePoolId =3D 332694bb-364a-434e-b23f-5fef985d3cbd, ignoreFailoverLimit =3D false, compatabilityVersion =3D null), log id: f1903fc 2012-09-20 12:42:54,614 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand] (pool-3-thread-50) FINISH, IsValidVDSCommand, return: true, log id: f19= 03fc 2012-09-20 12:42:54,653 INFO [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (pool-3-thread-50) START, IsVmDuringInitiatingVDSCommand(vmId =3D 509e608c-e657-473a-b031-f0811da96bde), log id: 5b0d9779 2012-09-20 12:42:54,655 INFO [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (pool-3-thread-50) FINISH, IsVmDuringInitiatingVDSCommand, return: fals= e, log id: 5b0d9779 2012-09-20 12:42:54,712 INFO [org.ovirt.engine.core.bll.RunVmCommand] (pool-3-thread-50) Running command: RunVmCommand internal: false. Entit= ies affected : ID: 509e608c-e657-473a-b031-f0811da96bde Type: VM 2012-09-20 12:42:54,800 INFO [org.ovirt.engine.core.vdsbroker.CreateVmVDSCommand] (pool-3-thread-50)= START, CreateVmVDSCommand(vdsId =3D 9840e840-02db-11e2-a01a-0011856cf23= e, vmId=3D509e608c-e657-473a-b031-f0811da96bde, vm=3Dorg.ovirt.engine.core.common.businessentities.VM@4432a01d), log id= : 554a0742 2012-09-20 12:42:54,825 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] (pool-3-thread-50) START, CreateVDSCommand(vdsId =3D 9840e840-02db-11e2-a01a-0011856cf23e, vmId=3D509e608c-e657-473a-b031-f0811da96bde, vm=3Dorg.ovirt.engine.core.common.businessentities.VM@4432a01d), log id= : 73615350 2012-09-20 12:42:54,912 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] (pool-3-thread-50) org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand spiceSslCipherSuite=3DDEFAULT,memSize=3D1024,kvmEnable=3Dtrue,smp=3D1,e= mulatedMachine=3Dpc-0.14,vmType=3Dkvm,keyboardLayout=3Den-us,pitReinjec= tion=3Dfalse,nice=3D0,display=3Dqxl,smpCoresPerSocket=3D1,spiceSecureCh= annels=3Dsmain,sinputs,scursor,splayback,srecord,sdisplay,displayNetwor= k=3Dovirtmgmt,timeOffset=3D-1,transparentHugePages=3Dtrue,vmId=3D509e60= 8c-e657-473a -b031-f0811da96bde,devices=3D [Ljava.util.Map;@41d42882,acpiEnable=3Dtrue,vmName=3DCentOS6Thames,cpuT= ype=3DConroe,custom=3D {device_bb912edd-9790-43ff-a758-f1d9f20cb5f5device_f5c86859-5ae9-4a37-9= d34-2b9547609622device_20a11f26-6a39-415d-a7bf-95893b9c55b5=3DVmId=3D50= 9e608c-e657-473a-b031-f0811da96bde,DeviceId=3D20a11f26-6a39-415d-a7bf-9= 5893b9c55b5,Device=3Dunix,Type=3Dchannel,BootOrder=3D0,SpecParams=3D {},Address=3D{port=3D1, bus=3D0, controller=3D0, type=3Dvirtio-serial},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3Df= alse,alias=3Dchannel0, device_bb912edd-9790-43ff-a758-f1d9f20cb5f5=3DVmId=3D509e608c-e657-473a= -b031-f0811da96bde,DeviceId=3Dbb912edd-9790-43ff-a758-f1d9f20cb5f5,Devi= ce=3Dide,Type=3Dcontroller,BootOrder=3D0,SpecParams=3D {},Address=3D{bus=3D0x00, domain=3D0x0000, type=3Dpci, slot=3D0x01, function=3D0x1},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3Dfalse,a= lias=3Dide0, device_bb912edd-9790-43ff-a758-f1d9f20cb5f5device_f5c86859-5ae9-4a37-9d= 34-2b9547609622=3DVmId=3D509e608c-e657-473a-b031-f0811da96bde,DeviceId=3D= f5c86859-5ae9-4a37-9d34-2b9547609622,Device=3Dvirtio-s erial,Type=3Dcontroller,BootOrder=3D0,SpecP= arams=3D {},Address=3D{bus=3D0x00, domain=3D0x0000, type=3Dpci, slot=3D0x04, function=3D0x0},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3Dfalse,a= lias=3Dvirtio-serial0, device_bb912edd-9790-43ff-a758-f1d9f20cb5f5device_f5c86859-5ae9-4a37-9d= 34-2b9547609622device_20a11f26-6a39-415d-a7bf-95893b9c55b5device_21f255= dc-9b3b-48d8-b8e4-63c1635e269b=3DVmId=3D509e608c-e657-473a-b031-f0811da= 96bde,DeviceId=3D21f255dc-9b3b-48d8-b8e4-63c1635e269b,Device=3Dspicevmc= ,Type=3Dchannel,BootOrder=3D0,SpecParams=3D {},A ddress=3D{port=3D2, bus=3D0, controller= =3D0, type=3Dvirtio-serial},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3Df= alse,alias=3Dchannel1, device_bb912edd-9790-43ff-a758-f1d9f20cb5f5device_f5c86859-5ae9-4a37-9d= 34-2b9547609622device_20a11f26-6a39-415d-a7bf-95893b9c55b5device_21f255= dc-9b3b-48d8-b8e4-63c1635e269bdevice_d6c2c4d1-da6b-44fe-a5aa-508135c7fd= fe=3DVmId=3D509e608c-e657-473a-b031-f0811da96bde,DeviceId=3Dd6c2c4d1-da= 6b-44fe-a5aa-508135c7fdfe,Device=3Dusb,Type=3Dcontroller,BootOrder=3D0,= SpecParams=3D {},Address=3D{bus=3D0x00, domain=3D 0x0000, = type=3Dpci, slot=3D0x01, function=3D0x2},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3Dfalse,a= lias=3Dusb0} 2012-09-20 12:42:54,982 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] (pool-3-thread-50) FINISH, CreateVDSCommand, log id: 73615350 2012-09-20 12:42:55,004 INFO [org.ovirt.engine.core.vdsbroker.CreateVmVDSCommand] (pool-3-thread-50)= IncreasePendingVms::CreateVmIncreasing vds hyper2.ovirt.com pending vcp= u count, now 1. Vm: CentOS6Thames 2012-09-20 12:42:55,012 INFO [org.ovirt.engine.core.vdsbroker.CreateVmVDSCommand] (pool-3-thread-50)= FINISH, CreateVmVDSCommand, return: WaitForLaunch, log id: 554a0742 2012-09-20 12:42:55,022 INFO [org.ovirt.engine.core.bll.RunVmCommand] (pool-3-thread-50) Lock freed to object EngineLock [exclusiveLocks=3D k= ey: 509e608c-e657-473a-b031-f0811da96bde value: VM , sharedLocks=3D ] 2012-09-20 12:42:56,434 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (QuartzScheduler_Worker-32) START, DestroyVDSCommand(vdsId =3D 9840e840-02db-11e2-a01a-0011856cf23e, vmId=3D509e608c-e657-473a-b031-f0811da96bde, force=3Dfalse, secondsToWa= it=3D0, gracefully=3Dfalse), log id: 6b44f6c9 2012-09-20 12:42:56,497 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (QuartzScheduler_Worker-32) FINISH, DestroyVDSCommand, log id: 6b44f6c9= 2012-09-20 12:42:56,532 INFO [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Worker-32) Running on vds during rerun failed vm: null= 2012-09-20 12:42:56,535 INFO [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Worker-32) vm CentOS6Thames running in db and not runn= ing in vds - add to rerun treatment. vds hyper2.ovirt.com 2012-09-20 12:42:56,548 ERROR [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Worker-32) Rerun vm 509e608c-e657-473a-b031-f0811da96b= de. Called from vds hyper2.ovirt.com 2012-09-20 12:42:56,582 INFO [org.ovirt.engine.core.vdsbroker.UpdateVdsDynamicDataVDSCommand] (pool-3-thread-50) START, UpdateVdsDynamicDataVDSCommand(vdsId =3D 9840e840-02db-11e2-a01a-0011856cf23e, vdsDynamic=3Dorg.ovirt.engine.core.common.businessentities.VdsDynamic@5= f1dd7c7), log id: 2a191f9e 2012-09-20 12:42:56,596 INFO [org.ovirt.engine.core.vdsbroker.UpdateVdsDynamicDataVDSCommand] (pool-3-thread-50) FINISH, UpdateVdsDynamicDataVDSCommand, log id: 2a19= 1f9e 2012-09-20 12:42:56,616 INFO [org.ovirt.engine.core.bll.RunVmCommand] (pool-3-thread-50) Lock Acquired to object EngineLock [exclusiveLocks=3D= key: 509e608c-e657-473a-b031-f0811da96bde value: VM , sharedLocks=3D ] 2012-09-20 12:42:56,632 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand] (pool-3-thread-50) START, IsValidVDSCommand(storagePoolId =3D 332694bb-364a-434e-b23f-5fef985d3cbd, ignoreFailoverLimit =3D false, compatabilityVersion =3D null), log id: 4629f11d 2012-09-20 12:42:56,636 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand] (pool-3-thread-50) FINISH, IsValidVDSCommand, return: true, log id: 4629f11d 2012-09-20 12:42:56,672 INFO [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (pool-3-thread-50) START, IsVmDuringInitiatingVDSCommand(vmId =3D 509e608c-e657-473a-b031-f0811da96bde), log id: f3a60e 2012-09-20 12:42:56,675 INFO [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (pool-3-thread-50) FINISH, IsVmDuringInitiatingVDSCommand, return: fals= e, log id: f3a60e 2012-09-20 12:42:56,713 WARN [org.ovirt.engine.core.bll.RunVmCommand] (pool-3-thread-50) CanDoAction of action RunVm failed. Reasons:VAR__ACTION__RUN,VAR__TYPE__VM,VAR__ACTION__RUN,VAR__TYPE__VM,V= AR__ACTION__RUN,VAR__TYPE__VM,VAR__ACTION__RUN,VAR__TYPE__VM,ACTION_TYP= E_FAILED_VDS_VM_CLUSTER 2012-09-20 12:42:56,717 INFO [org.ovirt.engine.core.bll.RunVmCommand] (pool-3-thread-50) Lock freed to object EngineLock [exclusiveLocks=3D k= ey: 509e608c-e657-473a-b031-f0811da96bde value: VM , sharedLocks=3D ] vdsm.log: Dummy-1960::DEBUG::2012-09-20 06:46:58,959::__init__::1249::Storage.Misc.excCmd::(_log) 'dd if=3D/rhev/data-center/332694bb-364a-434e-b23f-5fef985d3cbd/mastersd/do= m_md/inbox iflag=3Ddirect,fullblock count=3D1 bs=3D1024000' (cwd None) Dummy-1960::DEBUG::2012-09-20 06:46:59,043::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err= > =3D '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0488= 089 s, 21.0 MB/s\n'; <rc> =3D 0 Dummy-1960::DEBUG::2012-09-20 06:47:01,053::__init__::1249::Storage.Misc.excCmd::(_log) 'dd if=3D/rhev/data-center/332694bb-364a-434e-b23f-5fef985d3cbd/mastersd/do= m_md/inbox iflag=3Ddirect,fullblock count=3D1 bs=3D1024000' (cwd None) Dummy-1960::DEBUG::2012-09-20 06:47:01,136::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err= > =3D '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0477= 826 s, 21.4 MB/s\n'; <rc> =3D 0 Thread-7807::DEBUG::2012-09-20 06:47:01,991::BindingXMLRPC::859::vds::(wrapper) client [192.168.10.10]::call vmCreate with ({'custom': {'device_bb912edd-9790-43ff-a758-f1d9f20cb5f5device_f5c86859-5ae9-4a37-= 9d34-2b9547609622device_20a11f26-6a39-415d-a7bf-95893b9c55b5device_21f2= 55dc-9b3b-48d8-b8e4-63c1635e269bdevice_d6c2c4d1-da6b-44fe-a5aa-508135c7= fdfe': 'VmId=3D509e608c-e657-473a-b031-f0811da96bde,DeviceId=3Dd6c2c4d1-da6b-4= 4fe-a5aa-508135c7fdfe,Device=3Dusb,Type=3Dcontroller,BootOrder=3D0,Spec= Params=3D {},Address=3D{bus=3D0x00, domain=3D0x0000, type=3Dpci, slot=3D0x01, function=3D0x2},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3Dfalse,a= lias=3Dusb0', 'device_bb912edd-9790-43ff-a758-f1d9f20cb5f5device_f5c86859-5ae9-4a37-9= d34-2b9547609622device_20a11f26-6a39-415d-a7bf-95893b9c55b5device_21f25= 5dc-9b3b-48d8-b8e4-63c1635e269b': 'VmId=3D509e608c-e657-473a-b031-f0811da96bde,DeviceId=3D21f255dc-9b3b-4= 8d8-b8e4-63c1635e269b,Device=3Dspicevmc,Type=3Dchannel,BootOrder=3D0,Sp= ecParams=3D {},Address=3D{port=3D2, bus=3D0, controller=3D0, type=3Dvirtio-serial},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3Df= alse,alias=3Dchannel1', 'device_bb912edd-9790-43ff-a758-f1d9f20cb5f5device_f5c86859-5ae9-4a37-9= d34-2b9547609622': 'VmId=3D509e608c-e657-473a-b031-f0811da96bde,DeviceId=3Df5c86859-5ae9-4= a37-9d34-2b9547609622,Device=3Dvirtio-serial,Type=3Dcontroller,BootOrde= r=3D0,SpecParams=3D {},Address=3D{bus=3D0x00, domain=3D0x0000, type=3Dpci, slot=3D0x04, function=3D0x0},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3Dfalse,a= lias=3Dvirtio-serial0', 'device_bb912edd-9790-43ff-a758-f1d9f20cb5f5device_f5c86859-5ae9-4a37-9= d34-2b9547609622device_20a11f26-6a39-415d-a7bf-95893b9c55b5': 'VmId=3D509e608c-e657-473a-b031-f0811da96bde,DeviceId=3D20a11f26-6a39-4= 15d-a7bf-95893b9c55b5,Device=3Dunix,Type=3Dchannel,BootOrder=3D0,SpecPa= rams=3D {},Address=3D{port=3D1, bus=3D0, controller=3D0, type=3Dvirtio-serial},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3Df= alse,alias=3Dchannel0', 'device_bb912edd-9790-43ff-a758-f1d9f20cb5f5': 'VmId=3D509e608c-e657-473a-b031-f0811da96bde,DeviceId=3Dbb912edd-9790-4= 3ff-a758-f1d9f20cb5f5,Device=3Dide,Type=3Dcontroller,BootOrder=3D0,Spec= Params=3D {},Address=3D{bus=3D0x00, domain=3D0x0000, type=3Dpci, slot=3D0x01, function=3D0x1},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3Dfalse,a= lias=3Dide0'}, 'keyboardLayout': 'en-us', 'kvmEnable': 'true', 'pitReinjection': 'fals= e', 'acpiEnable': 'true', 'emulatedMachine': 'pc-0.14', 'displayNetwork': 'ovirtmgmt', 'vmId': '509e608c-e657-473a-b031-f0811da96bde', 'devices':= [{'device': 'qxl', 'specParams': {'vram': '65536'}, 'type': 'video', 'deviceId': '20c037f2-11e5-49a5-ace7-741023ec0ce9', 'address': {'bus': '0x00', ' slot': '0x02', ' domain': '0x0000', ' type': 'pci', ' functio= n': '0x0'}}, {'index': '2', 'iface': 'ide', 'specParams': {'path': ''}, 'readonly': 'true', 'deviceId': '1ed8a73e-be34-4829-a7e3-151a7a2efedc',= 'address': {' controller': '0', ' target': '0', 'unit': '0', ' bus': '1= ', ' type': 'drive'}, 'device': 'cdrom', 'path': '', 'type': 'disk'}, {'ifac= e': 'virtio', 'format': 'cow', 'type': 'disk', 'poolID': '332694bb-364a-434e-b23f-5fef985d3cbd', 'volumeID': 'f184ecd1-0001-4739-af71-250b412345d6', 'imageID': '0a7013db-68fd-4c42-bc2e-cc8d7a05ca18', 'specParams': {}, 'readonly': 'false', 'domainID': '26187d25-bfcb-40c7-97d1-667705ad2223', 'deviceId'= : '0a7013db-68fd-4c42-bc2e-cc8d7a05ca18', 'address': {'bus': '0x00', ' sl= ot': '0x05', ' domain': '0x0000', ' type': 'pci', ' function': '0x0'}, 'devi= ce': 'disk', 'shared': 'false', 'propagateErrors': 'off', 'optional': 'false= '}, {'nicModel': 'pv', 'macAddr': '00:1a:4a:a8:0a:00', 'network': 'ovirtmgm= t', 'specParams': {}, 'deviceId': '7392f689-2ba3-4243-9629-96b192b102a5', 'address': {'bus': '0x00', ' slot': '0x03', ' domain': '0x0000', ' type= ': 'pci', ' function': '0x0'}, 'device': 'bridge', 'type': 'interface'}, {'device': 'usb', 'specParams': {}, 'type': 'controller', 'deviceId': 'd6c2c4d1-da6b-44fe-a5aa-508135c7fdfe', 'address': {'bus': '0x00', ' sl= ot': '0x01', ' domain': '0x0000', ' type': 'pci', ' function': '0x2'}}, {'device': 'memballoon', 'specParams': {'model': 'virtio'}, 'type': 'balloon', 'deviceId': 'babd73a4-de64-4dce-91b9-e64c5b46c444'}], 'smp':= '1', 'vmType': 'kvm', 'timeOffset': ' -1', 'memSize': 1024, 'spiceSslCipherSuite': 'DEFAULT', 'cpuType': 'Conroe', 'spiceSecureChannels': 'smain,sinputs,scursor,splayback,srecord,sdisplay', 'smpCoresPerSocket'= : '1', 'vmName': 'CentOS6Thames', 'display': 'qxl', 'transparentHugePages= ': 'true', 'nice': '0'},) {} Thread-7807::INFO::2012-09-20 06:47:01,992::API::228::vds::(create) vmContainerLock acquired by vm 509e608c-e657-473a-b031-f0811da96bde Thread-7808::DEBUG::2012-09-20 06:47:01,996::vm::564::vm.Vm::(_startUnderlyingVm) vmId=3D`509e608c-e657-473a-b031-f0811da96bde`::Start Thread-7807::DEBUG::2012-09-20 06:47:01,996::API::244::vds::(create) To= tal desktops after creation of 509e608c-e657-473a-b031-f0811da96bde is 1 Thread-7808::DEBUG::2012-09-20 06:47:01,997::vm::568::vm.Vm::(_startUnderlyingVm) vmId=3D`509e608c-e657-473a-b031-f0811da96bde`::_ongoingCreations acquir= ed Thread-7807::DEBUG::2012-09-20 06:47:01,997::BindingXMLRPC::865::vds::(wrapper) return vmCreate with {'status': {'message': 'Done', 'code': 0}, 'vmList': {'status': 'WaitForLaunch', 'acpiEnable': 'true', 'emulatedMachine': 'pc-0.14', 'vmId': '509e608c-e657-473a-b031-f0811da96bde', 'pid': '0', 'timeOffset= ': '-1', 'displayPort': '-1', 'displaySecurePort': '-1', 'spiceSslCipherSuite': 'DEFAULT', 'cpuType': 'Conroe', 'custom': {'device_bb912edd-9790-43ff-a758-f1d9f20cb5f5device_f5c86859-5ae9-4a37-= 9d34-2b9547609622device_20a11f26-6a39-415d-a7bf-95893b9c55b5device_21f2= 55dc-9b3b-48d8-b8e4-63c1635e269bdevice_d6c2c4d1-da6b-44fe-a5aa-508135c7= fdfe': 'VmId=3D509e608c-e657-473a-b031-f0811da96bde,DeviceId=3Dd6c2c4d1-da6b-4= 4fe-a5aa-508135c7fdfe,Device=3Dusb,Type=3Dcontroller,BootOrder=3D0,Spec= Params=3D {},Address=3D{bus=3D0x00, domain=3D0x0000, type=3Dpci, slot=3D0x01, function=3D0x2},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3Dfalse,a= lias=3Dusb0', 'device_bb912edd-9790-43ff-a758-f1d9f20cb5f5device_f5c86859-5ae9-4a37-9= d34-2b9547609622device_20a11f26-6a39-415d-a7bf-95893b9c55b5device_21f25= 5dc-9b3b-48d8-b8e4-63c1635e269b': 'VmId=3D509e608c-e657-473a-b031-f0811da96bde,DeviceId=3D21f255dc-9b3b-4= 8d8-b8e4-63c1635e269b,Device=3Dspicevmc,Type=3Dchannel,BootOrder=3D0,Sp= ecParams=3D {},Address=3D{port=3D2, bus=3D0, controller=3D0, type=3Dvirtio-serial},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3Df= alse,alias=3Dchannel1', 'device_bb912edd-9790-43ff-a758-f1d9f20cb5f5device_f5c86859-5ae9-4a37-9= d34-2b9547609622': 'VmId=3D509e608c-e657-473a-b031-f0811da96bde,DeviceId=3Df5c86859-5ae9-4= a37-9d34-2b9547609622,Device=3Dvirtio-serial,Type=3Dcontroller,BootOrde= r=3D0,SpecParams=3D {},Address=3D{bus=3D0x00, domain=3D0x0000, type=3Dpci, slot=3D0x04, function=3D0x0},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3Dfalse,a= lias=3Dvirtio-serial0', 'device_bb912edd-9790-43ff-a758-f1d9f20cb5f5device_f5c86859-5ae9-4a37-9= d34-2b9547609622device_20a11f26-6a39-415d-a7bf-95893b9c55b5': 'VmId=3D509e608c-e657-473a-b031-f0811da96bde,DeviceId=3D20a11f26-6a39-4= 15d-a7bf-95893b9c55b5,Device=3Dunix,Type=3Dchannel,BootOrder=3D0,SpecPa= rams=3D {},Address=3D{port=3D1, bus=3D0, controller=3D0, type=3Dvirtio-serial},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3Df= alse,alias=3Dchannel0', 'device_bb912edd-9790-43ff-a758-f1d9f20cb5f5': 'VmId=3D509e608c-e657-473a-b031-f0811da96bde,DeviceId=3Dbb912edd-9790-4= 3ff-a758-f1d9f20cb5f5,Device=3Dide,Type=3Dcontroller,BootOrder=3D0,Spec= Params=3D {},Address=3D{bus=3D0x00, domain=3D0x0000, type=3Dpci, slot=3D0x01, function=3D0x1},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3Dfalse,a= lias=3Dide0'}, 'clientIp': '', 'nicModel': 'rtl8139,pv', 'keyboardLayout': 'en-us', 'kvmEnable': 'true', 'pitReinjection': 'false', 'transparentHugePages':= 'true', 'displayNetwork': 'ovirtmgmt', 'devices': [{'device': 'qxl', 'specParams': {'vram': '65536'}, 'type': 'video', 'deviceId': '20c037f2-11e5-49a5-ace7-741023ec0ce9', 'address': {'bus': '0x00', ' sl= ot': '0x02', ' domain': '0x0000', ' type': 'pci', ' function': '0x0'}}, {'index': '2', 'iface': 'ide', 'specParams': {'path': ''}, 'readonly': 'true', 'deviceId': '1ed8a73e-be34-4829-a7e3-151a7a2efedc', 'address': = {' controller': '0', ' target': '0', 'unit': '0', ' bus': '1', ' type': 'drive'}, 'device': 'cdrom', 'path': '', 'type': 'disk'}, {'iface': 'virtio', 'format': 'cow', 'type': 'disk', 'poolID': '332694bb-364a-434e-b23f-5fef985d3cbd', 'volumeID': 'f184ecd1-0001-4739-af71-250b412345d6', 'imageID': '0a7013db-68fd-4c42-bc2e-cc8d7a05ca18', 'specParams': {}, 'readonly': 'false', 'domainID': '26187d25-bfcb-40c7-97d1-667705ad2223', 'deviceId'= : '0a7013db-68fd-4c42-bc2e-cc8d7a05ca18', 'address': {'bus': '0x00', ' sl= ot': '0x05', ' domain': '0x0000', ' type': 'pci', ' function': '0x0'}, 'devi= ce': 'disk', 'shared': 'false', 'propagateErrors': 'off', 'optional': 'false= '}, {'nicModel': 'pv', 'macAddr': '00:1a:4a:a8:0a:00', 'network': 'ovirtmgm= t', 'specParams': {}, 'deviceId': '7392f689-2ba3-4243-9629-96b192b102a5', 'address': {'bus': '0x00', ' slot': '0x03', ' domain': '0x0000', ' type= ': 'pci', ' function': '0x0'}, 'device': 'bridge', 'type': 'interface'}, {'device': 'usb', 'specParams': {}, 'type': 'controller', 'deviceId': 'd6c2c4d1-da6b-44fe-a5aa-508135c7fdfe', 'address': {'b us': '0x00', ' slot': '0x01', ' domain': '0x0000', ' type': 'pci', ' function': '0x2'}}, {'device': 'memballoon', 'specParams': {'model': 'virtio'}, 'type': 'balloon', 'deviceId': 'babd73a4-de64-4dce-91b9-e64c5b46c444'}], 'smp': '1', 'vmType': 'kvm', 'memSize': 1024, 'displayIp': '192.168.10.13', 'spiceSecureChannels': 'smain,sinputs,scursor,splayback,srecord,sdisplay', 'smpCoresPerSocket'= : '1', 'vmName': 'CentOS6Thames', 'display': 'qxl', 'nice': '0'}} Thread-7808::INFO::2012-09-20 06:47:01,997::libvirtvm::1285::vm.Vm::(_r= un) vmId=3D`509e608c-e657-473a-b031-f0811da96bde`::VM wrapper has started Thread-7808::DEBUG::2012-09-20 06:47:02,000::task::588::TaskManager.Task::(_updateState) Task=3D`b6ef82b2-2986-4b7b-95ba-d5f3cac8ad31`::moving from state init -= > state preparing Thread-7808::INFO::2012-09-20 06:47:02,001::logUtils::37::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID=3D'26187d25-bfcb-40c7-97d1-667705ad2223', spUUID=3D'332694bb-364a-434e-b23f-5fef985d3cbd', imgUUID=3D'0a7013db-68fd-4c42-bc2e-cc8d7a05ca18', volUUID=3D'f184ecd1-0001-4739-af71-250b412345d6', options=3DNone) Thread-7808::DEBUG::2012-09-20 06:47:02,001::resourceManager::175::ResourceManager.Request::(__init__)= ResName=3D`Storage.26187d25-bfcb-40c7-97d1-667705ad2223`ReqID=3D`83dac2= e0-3d55-4ef6-abf3-7b2561814ab4`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at= 'registerResource' Thread-7808::DEBUG::2012-09-20 06:47:02,002::resourceManager::486::ResourceManager::(registerResource)= Trying to register resource 'Storage.26187d25-bfcb-40c7-97d1-667705ad22= 23' for lock type 'shared' Thread-7808::DEBUG::2012-09-20 06:47:02,002::resourceManager::528::ResourceManager::(registerResource)= Resource 'Storage.26187d25-bfcb-40c7-97d1-667705ad2223' is free. Now locking as 'shared' (1 active user) Thread-7808::DEBUG::2012-09-20 06:47:02,002::resourceManager::212::ResourceManager.Request::(grant) ResName=3D`Storage.26187d25-bfcb-40c7-97d1-667705ad2223`ReqID=3D`83dac2= e0-3d55-4ef6-abf3-7b2561814ab4`::Granted request Thread-7808::DEBUG::2012-09-20 06:47:02,003::task::817::TaskManager.Task::(resourceAcquired) Task=3D`b6ef82b2-2986-4b7b-95ba-d5f3cac8ad31`::_resourcesAcquired: Storage.26187d25-bfcb-40c7-97d1-667705ad2223 (shared) Thread-7808::DEBUG::2012-09-20 06:47:02,003::task::978::TaskManager.Task::(_decref) Task=3D`b6ef82b2-2986-4b7b-95ba-d5f3cac8ad31`::ref 1 aborting False Thread-7808::INFO::2012-09-20 06:47:02,004::logUtils::39::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '13958643712', 'apparentsi= ze': '13958643712'} Thread-7808::DEBUG::2012-09-20 06:47:02,004::task::1172::TaskManager.Task::(prepare) Task=3D`b6ef82b2-2986-4b7b-95ba-d5f3cac8ad31`::finished: {'truesize': '13958643712', 'apparentsize': '13958643712'} Thread-7808::DEBUG::2012-09-20 06:47:02,004::task::588::TaskManager.Task::(_updateState) Task=3D`b6ef82b2-2986-4b7b-95ba-d5f3cac8ad31`::moving from state prepar= ing -> state finished Thread-7808::DEBUG::2012-09-20 06:47:02,004::resourceManager::809::ResourceManager.Owner::(releaseAll)= Owner.releaseAll requests {} resources {'Storage.26187d25-bfcb-40c7-97d1-667705ad2223': < ResourceRef 'Storage.26187d25-bfcb-40c7-97d1-667705ad2223', isValid: 'True' obj: 'None'>} Thread-7808::DEBUG::2012-09-20 06:47:02,004::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-7808::DEBUG::2012-09-20 06:47:02,005::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.26187d25-bfcb-40c7-97d1-667705ad222= 3' Thread-7808::DEBUG::2012-09-20 06:47:02,005::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.26187d25-bfcb-40c7-97d1-667705ad2223' (0 act= ive users) Thread-7808::DEBUG::2012-09-20 06:47:02,005::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.26187d25-bfcb-40c7-97d1-667705ad2223' is free, findin= g out if anyone is waiting for it. Thread-7808::DEBUG::2012-09-20 06:47:02,005::resourceManager::565::ResourceManager::(releaseResource) = No one is waiting for resource 'Storage.26187d25-bfcb-40c7-97d1-667705ad22= 23', Clearing records. Thread-7808::DEBUG::2012-09-20 06:47:02,005::task::978::TaskManager.Task::(_decref) Task=3D`b6ef82b2-2986-4b7b-95ba-d5f3cac8ad31`::ref 0 aborting False Thread-7808::INFO::2012-09-20 06:47:02,006::clientIF::274::vds::(prepareVolumePath) prepared volume p= ath: Thread-7808::DEBUG::2012-09-20 06:47:02,006::task::588::TaskManager.Task::(_updateState) Task=3D`83579cfe-4384-4b76-8bb0-979ed2b60739`::moving from state init -= > state preparing Thread-7808::INFO::2012-09-20 06:47:02,006::logUtils::37::dispatcher::(wrapper) Run and protect: prepareImage(sdUUID=3D'26187d25-bfcb-40c7-97d1-667705ad2223', spUUID=3D'332694bb-364a-434e-b23f-5fef985d3cbd', imgUUID=3D'0a7013db-68fd-4c42-bc2e-cc8d7a05ca18', volUUID=3D'f184ecd1-0001-4739-af71-250b412345d6') Thread-7808::DEBUG::2012-09-20 06:47:02,007::resourceManager::175::ResourceManager.Request::(__init__)= ResName=3D`Storage.26187d25-bfcb-40c7-97d1-667705ad2223`ReqID=3D`c22e62= 09-b86d-448c-8884-372ce9a589c4`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at= 'registerResource' Thread-7808::DEBUG::2012-09-20 06:47:02,007::resourceManager::486::ResourceManager::(registerResource)= Trying to register resource 'Storage.26187d25-bfcb-40c7-97d1-667705ad22= 23' for lock type 'shared' Thread-7808::DEBUG::2012-09-20 06:47:02,007::resourceManager::528::ResourceManager::(registerResource)= Resource 'Storage.26187d25-bfcb-40c7-97d1-667705ad2223' is free. Now locking as 'shared' (1 active user) Thread-7808::DEBUG::2012-09-20 06:47:02,007::resourceManager::212::ResourceManager.Request::(grant) ResName=3D`Storage.26187d25-bfcb-40c7-97d1-667705ad2223`ReqID=3D`c22e62= 09-b86d-448c-8884-372ce9a589c4`::Granted request Thread-7808::DEBUG::2012-09-20 06:47:02,008::task::817::TaskManager.Task::(resourceAcquired) Task=3D`83579cfe-4384-4b76-8bb0-979ed2b60739`::_resourcesAcquired: Storage.26187d25-bfcb-40c7-97d1-667705ad2223 (shared) Thread-7808::DEBUG::2012-09-20 06:47:02,008::task::978::TaskManager.Task::(_decref) Task=3D`83579cfe-4384-4b76-8bb0-979ed2b60739`::ref 1 aborting False Thread-7808::DEBUG::2012-09-20 06:47:02,008::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/dd iflag=3Ddirect skip=3D4 bs=3D512 if=3D/dev/26187d25-bfcb-40c7-97d1-667705ad2223/metadata count=3D1' (cwd= None) Thread-7808::DEBUG::2012-09-20 06:47:02,023::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err= > =3D '1+0 records in\n1+0 records out\n512 bytes (512 B) copied, 0.000766795= s, 668 kB/s\n'; <rc> =3D 0 Thread-7808::DEBUG::2012-09-20= 06:47:02,023::misc::314::Storage.Misc::(validateDDBytes) err: ['1+0 rec= ords in', '1+0 records out', '512 bytes (512 B) copied, 0.000766795 s, 668 kB/s'], size: 512 Thread-7808::INFO::2012-09-20 06:47:02,023::image::357::Storage.Image::(getChain) sdUUID=3D26187d25-bfcb-40c7-97d1-667705ad2223 imgUUID=3D0a7013db-68fd-4c42-bc2e-cc8d7a05ca18 chain=3D [<storage.blockVolume.BlockVolume instance at 0x7ff9fc0feb90>] Thread-7808::INFO::2012-09-20 06:47:02,024::logUtils::39::dispatcher::(wrapper) Run and protect: prepareImage, Return response: {'path': '/rhev/data-center/332694bb-364a-434e-b23f-5fef985d3cbd/26187d25-bfcb-4= 0c7-97d1-667705ad2223/images/0a7013db-68fd-4c42-bc2e-cc8d7a05ca18/f184e= cd1-0001-4739-af71-250b412345d6', 'chain': [{'path': '/rhev/data-center/332694bb-364a-434e-b23f-5fef985d3cbd/26187d25-bfcb-4= 0c7-97d1-667705ad2223/images/0a7013db-68fd-4c42-bc2e-cc8d7a05ca18/f184e= cd1-0001-4739-af71-250b412345d6', 'domainID': '26187d25-bfcb-40c7-97d1-667705ad2223', 'volumeID': 'f184ecd1-0001-4739-af71-250b412345d6', 'imageID': '0a7013db-68fd-4c42-bc2e-cc8d7a05ca18'}]} Thread-7808::DEBUG::2012-09-20 06:47:02,024::task::1172::TaskManager.Task::(prepare) Task=3D`83579cfe-4384-4b76-8bb0-979ed2b60739`::finished: {'path': '/rhev/data-center/332694bb-364a-434e-b23f-5fef985d3cbd/26187d25-bfcb-4= 0c7-97d1-667705ad2223/images/0a7013db-68fd-4c42-bc2e-cc8d7a05ca18/f184e= cd1-0001-4739-af71-250b412345d6', 'chain': [{'path': '/rhev/data-center/332694bb-364a-434e-b23f-5fef985d3cbd/26187d25-bfcb-4= 0c7-97d1-667705ad2223/images/0a7013db-68fd-4c42-bc2e-cc8d7a05ca18/f184e= cd1-0001-4739-af71-250b412345d6', 'domainID': '26187d25-bfcb-40c7-97d1-667705ad2223', 'volumeID': 'f184ecd1-0001-4739-af71-250b412345d6', 'imageID': '0a7013db-68fd-4c42-bc2e-cc8d7a05ca18'}]} Thread-7808::DEBUG::2012-09-20 06:47:02,024::task::588::TaskManager.Task::(_updateState) Task=3D`83579cfe-4384-4b76-8bb0-979ed2b60739`::moving from state prepar= ing -> state finished Thread-7808::DEBUG::2012-09-20 06:47:02,025::resourceManager::809::ResourceManager.Owner::(releaseAll)= Owner.releaseAll requests {} resources {'Storage.26187d25-bfcb-40c7-97d1-667705ad2223': < ResourceRef 'Storage.26187d25-bfcb-40c7-97d1-667705ad2223', isValid: 'True' obj: 'None'>} Thread-7808::DEBUG::2012-09-20 06:47:02,025::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-7808::DEBUG::2012-09-20 06:47:02,025::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.26187d25-bfcb-40c7-97d1-667705ad222= 3' Thread-7808::DEBUG::2012-09-20 06:47:02,025::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.26187d25-bfcb-40c7-97d1-667705ad2223' (0 act= ive users) Thread-7808::DEBUG::2012-09-20 06:47:02,026::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.26187d25-bfcb-40c7-97d1-667705ad2223' is free, findin= g out if anyone is waiting for it. Thread-7808::DEBUG::2012-09-20 06:47:02,026::resourceManager::565::ResourceManager::(releaseResource) = No one is waiting for resource 'Storage.26187d25-bfcb-40c7-97d1-667705ad22= 23', Clearing records. Thread-7808::DEBUG::2012-09-20 06:47:02,026::task::978::TaskManager.Task::(_decref) Task=3D`83579cfe-4384-4b76-8bb0-979ed2b60739`::ref 0 aborting False Thread-7808::INFO::2012-09-20 06:47:02,026::clientIF::274::vds::(prepareVolumePath) prepared volume path: /rhev/data-center/332694bb-364a-434e-b23f-5fef985d3cbd/26187d25-b= fcb-40c7-97d1-667705ad2223/images/0a7013db-68fd-4c42-bc2e-cc8d7a05ca18/= f184ecd1-0001-4739-af71-250b412345d6 Thread-7808::DEBUG::2012-09-20 06:47:02,037::libvirtvm::1338::vm.Vm::(_= run) vmId=3D`509e608c-e657-473a-b031-f0811da96bde`::<?xml version=3D"1.0" encoding=3D"utf-8"?> <domain type=3D"kvm"> <name>CentOS6Thames</name> <uuid>509e608c-e657-473a-b031-f0811da96bde</uuid> <memory>1048576</memory> <currentMemory>1048576</currentMemory> <vcpu>1</vcpu> <devices> <channel type=3D"unix"> <target name=3D"com.redhat.rhevm.vdsm" type=3D"virtio"/> <source mode=3D"bind" path=3D"/var/lib/libvirt/qemu/channels/CentOS6Thames.com.redhat.rhevm.v= dsm"/> </channel> <input bus=3D"ps2" type=3D"mouse"/> <channel type=3D"spicevmc"> <target name=3D"com.redhat.spice.0" type=3D"vir= tio"/> </channel> <graphics autoport=3D"yes" keymap=3D"en-us" passwd=3D"*= ****" passwdValidTo=3D"1970-01-01T00:00:01" port=3D"-1" tlsPort=3D"-1" type=3D= "spice"> <channel mode=3D"secure" name=3D"main"/> <channel mode=3D"secure" name=3D"inputs"/> <channel mode=3D"secure" name=3D"cursor"/> <channel mode=3D"secure" name=3D"playback"/> <channel mode=3D"secure" name=3D"record"/> <channel mode=3D"secure" name=3D"display"/> <listen network=3D"vdsm-ovirtmgmt" type=3D"netw= ork"/> </graphics> <console type=3D"pty"> <target port=3D"0" type=3D"virtio"/> </console> <controller type=3D"usb"> <address domain=3D"0x0000" function=3D"0x2" slot=3D"0x01" type=3D"pci" bus=3D"0x00"/> </controller> <video> <address domain=3D"0x0000" function=3D"0x0" slot=3D"0x02" type=3D"pci" bus=3D"0x00"/> <model heads=3D"1" type=3D"qxl" vram=3D"65536"/= > </video> <interface type=3D"bridge"> <address domain=3D"0x0000" function=3D"0x0" slot=3D"0x03" type=3D"pci" bus=3D"0x00"/> <mac address=3D"00:1a:4a:a8:0a:00"/> <model type=3D"virtio"/> <source bridge=3D"ovirtmgmt"/> </interface> <memballoon model=3D"virtio"/> <disk device=3D"cdrom" snapshot=3D"no" type=3D"file"> <address bus=3D"1" controller=3D"0" target=3D= "0" type=3D"drive" unit=3D"0"/> <source file=3D"" startupPolicy=3D"optional"/> <target bus=3D"ide" dev=3D"hdc"/> <readonly/> <serial></serial> </disk> <disk device=3D"disk" snapshot=3D"no" type=3D"block"> <address domain=3D"0x0000" function=3D"0x0" slot=3D"0x05" type=3D"pci" bus=3D"0x00"/> <source dev=3D"/rhev/data-center/332694bb-364a-434e-b23f-5fef985d3cbd/26187d25-= bfcb-40c7-97d1-667705ad2223/images/0a7013db-68fd-4c42-bc2e-cc8d7a05ca18= /f184ecd1-0001-4739-af71-250b412345d6"/> <target bus=3D"virtio" dev=3D"vda"/> <serial>0a7013db-68fd-4c42-bc2e-cc8d7a05ca18</serial> <driver cache=3D"none" error_policy=3D"stop" io=3D"native" name=3D"qemu" type=3D"qcow2"/> </disk> </devices> <os> <type arch=3D"x86_64" machine=3D"pc-0.14">hvm</type> <smbios mode=3D"sysinfo"/> </os> <sysinfo type=3D"smbios"> <system> <entry name=3D"manufacturer">Red Hat</entry> <entry name=3D"product">RHEV Hypervisor</entry>= <entry name=3D"version">17-1</entry> <entry name=3D"serial">31323334-3535-4C44-3643-4D5633393936_00:19:bb:39:97:4a<= /entry> <entry name=3D"uuid">509e608c-e657-473a-b031-f0811da96bde</entry> </system> </sysinfo> <clock adjustment=3D"-1" offset=3D"variable"> <timer name=3D"rtc" tickpolicy=3D"catchup"/> </clock> <features> <acpi/> </features> <cpu match=3D"exact"> <model>Conroe</model> <topology cores=3D"1" sockets=3D"1" threads=3D"1"/> </cpu> </domain> Thread-7808::DEBUG::2012-09-20 06:47:02,426::vm::580::vm.Vm::(_startUnderlyingVm) vmId=3D`509e608c-e657-473a-b031-f0811da96bde`::_ongoingCreations releas= ed Thread-7808::ERROR::2012-09-20 06:47:02,427::vm::604::vm.Vm::(_startUnderlyingVm) vmId=3D`509e608c-e657-473a-b031-f0811da96bde`::The vm start process fai= led Traceback (most recent call last): File "/usr/share/vdsm/vm.py", line 570, in _startUnderlyingVm File "/usr/share/vdsm/libvirtvm.py", line 1364, in _run File "/usr/lib/python2.7/site-packages/vdsm/libvirtconnection.py", li= ne 82, in wrapper File "/usr/lib64/python2.7/site-packages/libvirt.py", line 2420, in createXML libvirtError: unsupported configuration: spice secure channels set in X= ML configuration, but TLS is disabled in qemu.conf Thread-7808::DEBUG::2012-09-20 06:47:02,430::vm::920::vm.Vm::(setDownStatus) vmId=3D`509e608c-e657-473a-b031-f0811da96bde`::Changed state to Down: unsupported configuration: spice secure channels set in XML configurati= on, but TLS is disabled in qemu.conf Dummy-1960::DEBUG::2012-09-20 06:47:03,145::__init__::1249::Storage.Misc.excCmd::(_log) 'dd if=3D/rhev/data-center/332694bb-364a-434e-b23f-5fef985d3cbd/mastersd/do= m_md/inbox iflag=3Ddirect,fullblock count=3D1 bs=3D1024000' (cwd None) Dummy-1960::DEBUG::2012-09-20 06:47:03,230::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err= > =3D '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0496= 138 s, 20.6 MB/s\n'; <rc> =3D 0 Thread-7810::DEBUG::2012-09-20 06:47:03,560::BindingXMLRPC::156::vds::(wrapper) [192.168.10.10] Thread-7810::DEBUG::2012-09-20 06:47:03,561::task::588::TaskManager.Task::(_updateState) Task=3D`9bc08c7e-010f-45c2-940a-3fd8361785d5`::moving from state init -= > state preparing Thread-7810::INFO::2012-09-20 06:47:03,561::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID=3D'332694bb-364a-434e-b23f-5fef985d3cbd', options=3D= None) Thread-7810::INFO::2012-09-20 06:47:03,562::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 3, 'spmStatus': 'SP= M', 'spmLver': 0}} Thread-7810::DEBUG::2012-09-20 06:47:03,562::task::1172::TaskManager.Task::(prepare) Task=3D`9bc08c7e-010f-45c2-940a-3fd8361785d5`::finished: {'spm_st': {'s= pmId': 3, 'spmStatus': 'SPM', 'spmLver': 0}} Thread-7810::DEBUG::2012-09-20 06:47:03,562::task::588::TaskManager.Task::(_updateState) Task=3D`9bc08c7e-010f-45c2-940a-3fd8361785d5`::moving from state prepar= ing -> state finished Thread-7810::DEBUG::2012-09-20 06:47:03,562::resourceManager::809::ResourceManager.Owner::(releaseAll)= Owner.releaseAll requests {} resources {} Thread-7810::DEBUG::2012-09-20 06:47:03,562::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-7810::DEBUG::2012-09-20 06:47:03,563::task::978::TaskManager.Task::(_decref) Task=3D`9bc08c7e-010f-45c2-940a-3fd8361785d5`::ref 0 aborting False Thread-7812::DEBUG::2012-09-20 06:47:03,595::BindingXMLRPC::156::vds::(wrapper) [192.168.10.10] Thread-7812::DEBUG::2012-09-20 06:47:03,595::task::588::TaskManager.Task::(_updateState) Task=3D`8e330204-753f-422d-b286-a360410806be`::moving from state init -= > state preparing Thread-7812::INFO::2012-09-20 06:47:03,596::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID=3D'332694bb-364a-434e-b23f-5fef985d3cbd', options=3DNone) Thread-7812::DEBUG::2012-09-20 06:47:03,596::resourceManager::175::ResourceManager.Request::(__init__)= ResName=3D`Storage.332694bb-364a-434e-b23f-5fef985d3cbd`ReqID=3D`a72228= 34-3565-4e28-a15f-72692ef664c6`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at= 'registerResource' Thread-7812::DEBUG::2012-09-20 06:47:03,596::resourceManager::486::ResourceManager::(registerResource)= Trying to register resource 'Storage.332694bb-364a-434e-b23f-5fef985d3c= bd' for lock type 'shared' Thread-7812::DEBUG::2012-09-20 06:47:03,597::resourceManager::528::ResourceManager::(registerResource)= Resource 'Storage.332694bb-364a-434e-b23f-5fef985d3cbd' is free. Now locking as 'shared' (1 active user) Thread-7812::DEBUG::2012-09-20 06:47:03,597::resourceManager::212::ResourceManager.Request::(grant) ResName=3D`Storage.332694bb-364a-434e-b23f-5fef985d3cbd`ReqID=3D`a72228= 34-3565-4e28-a15f-72692ef664c6`::Granted request Thread-7812::DEBUG::2012-09-20 06:47:03,597::task::817::TaskManager.Task::(resourceAcquired) Task=3D`8e330204-753f-422d-b286-a360410806be`::_resourcesAcquired: Storage.332694bb-364a-434e-b23f-5fef985d3cbd (shared) Thread-7812::DEBUG::2012-09-20 06:47:03,598::task::978::TaskManager.Task::(_decref) Task=3D`8e330204-753f-422d-b286-a360410806be`::ref 1 aborting False Thread-7813::DEBUG::2012-09-20 06:47:03,598::BindingXMLRPC::859::vds::(wrapper) client [192.168.10.10]::call vmGetStats with ('509e608c-e657-473a-b031-f0811da96bde',) {} Thread-7812::INFO::2012-09-20 06:47:03,599::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 3, 'master_uui= d': '26187d25-bfcb-40c7-97d1-667705ad2223', 'name': 'Valeka', 'version': '2= ', 'domains': u'26187d25-bfcb-40c7-97d1-667705ad2223:Active,90104c3d-837b-47dd-8c82-d= da92eec30d9:Active', 'pool_status': 'connected', 'isoprefix': u'/rhev/data-center/332694bb-364a-434e-b23f-5fef985d3cbd/90104c3d-837b-= 47dd-8c82-dda92eec30d9/images/11111111-1111-1111-1111-111111111111', 'type': 'ISCSI', 'master_ver': 1, 'lver': 0}, 'dominfo': {u'26187d25-bfcb-40c7-97d1-667705ad2223': {'status': u'Active', 'diskfr= ee': '1674097721344', 'alerts': [], 'disktotal': '1799591297024'}, u'90104c3d-837b-47dd-8c82-dda92eec30d9': {'status': u'Active', 'diskfre= e': '423518535680', 'alerts': [], 'disktotal': '492264226816'}}} Thread-7813::DEBUG::2012-09-20 06:47:03,600::BindingXMLRPC::865::vds::(wrapper) return vmGetStats with= {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Do= wn', 'hash': '0', 'exitMessage': 'unsupported configuration: spice secure channels set in XML configuration, but TLS is disabled in qemu.conf', 'vmId': '509e608c-e657-473a-b031-f0811da96bde', 'timeOffset': '-1', 'exitCode': 1}]} Thread-7812::DEBUG::2012-09-20 06:47:03,600::task::1172::TaskManager.Task::(prepare) Task=3D`8e330204-753f-422d-b286-a360410806be`::finished: {'info': {'spm= _id': 3, 'master_uuid': '26187d25-bfcb-40c7-97d1-667705ad2223', 'name': 'Vale= ka', 'version': '2', 'domains': u'26187d25-bfcb-40c7-97d1-667705ad2223:Active,90104c3d-837b-47dd-8c82-d= da92eec30d9:Active', 'pool_status': 'connected', 'isoprefix': u'/rhev/data-center/332694bb-364a-434e-b23f-5fef985d3cbd/90104c3d-837b-= 47dd-8c82-dda92eec30d9/images/11111111-1111-1111-1111-111111111111', 'type': 'ISCSI', 'master_ver': 1, 'lver': 0}, 'dominfo': {u'26187d25-bfcb-40c7-97d1-667705ad2223': {'status': u'Active', 'diskfr= ee': '1674097721344', 'alerts': [], 'disktotal': '1799591297024'}, u'90104c3d-837b-47dd-8c82-dda92eec30d9': {'status': u'Active', 'diskfre= e': '423518535680', 'alerts': [], 'disktotal': '492264226816'}}} Thread-7812::DEBUG::2012-09-20 06:47:03,601::task::588::TaskManager.Task::(_updateState) Task=3D`8e330204-753f-422d-b286-a360410806be`::moving from state prepar= ing -> state finished Thread-7812::DEBUG::2012-09-20 06:47:03,601::resourceManager::809::ResourceManager.Owner::(releaseAll)= Owner.releaseAll requests {} resources {'Storage.332694bb-364a-434e-b23f-5fef985d3cbd': < ResourceRef 'Storage.332694bb-364a-434e-b23f-5fef985d3cbd', isValid: 'True' obj: 'None'>} Thread-7812::DEBUG::2012-09-20 06:47:03,601::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-7812::DEBUG::2012-09-20 06:47:03,602::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.332694bb-364a-434e-b23f-5fef985d3cb= d' Thread-7812::DEBUG::2012-09-20 06:47:03,602::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.332694bb-364a-434e-b23f-5fef985d3cbd' (0 act= ive users) Thread-7812::DEBUG::2012-09-20 06:47:03,602::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.332694bb-364a-434e-b23f-5fef985d3cbd' is free, findin= g out if anyone is waiting for it. Thread-7812::DEBUG::2012-09-20 06:47:03,602::resourceManager::565::ResourceManager::(releaseResource) = No one is waiting for resource 'Storage.332694bb-364a-434e-b23f-5fef985d3c= bd', Clearing records. Thread-7812::DEBUG::2012-09-20 06:47:03,602::task::978::TaskManager.Task::(_decref) Task=3D`8e330204-753f-422d-b286-a360410806be`::ref 0 aborting False Thread-7814::DEBUG::2012-09-20 06:47:03,658::BindingXMLRPC::859::vds::(wrapper) client [192.168.10.10]::call vmDestroy with ('509e608c-e657-473a-b031-f0811da96bde',) {} Thread-7814::INFO::2012-09-20 06:47:03,658::API::317::vds::(destroy) vmContainerLock acquired by vm 509e608c-e657-473a-b031-f0811da96bde Thread-7814::DEBUG::2012-09-20 06:47:03,658::libvirtvm::2085::vm.Vm::(destroy) vmId=3D`509e608c-e657-473a-b031-f0811da96bde`::destroy Called Thread-7814::INFO::2012-09-20 06:47:03,658::libvirtvm::2040::vm.Vm::(releaseVm) vmId=3D`509e608c-e657-473a-b031-f0811da96bde`::Release VM resources Thread-7814::WARNING::2012-09-20 06:47:03,659::vm::328::vm.Vm::(_set_lastStatus) vmId=3D`509e608c-e657-473a-b031-f0811da96bde`::trying to set state to Powering down when already Down Thread-7814::DEBUG::2012-09-20 06:47:03,659::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sud= o -n /usr/sbin/service ksmtuned retune' (cwd None) Thread-7814::DEBUG::2012-09-20 06:47:03,696::__init__::1249::Storage.Misc.excCmd::(_log) FAILED: <err>= =3D 'Redirecting to /bin/systemctl retune ksmtuned.service\nUnknown operat= ion retune\n'; <rc> =3D 1 Thread-7814::DEBUG::2012-09-20 06:47:03,697::task::588::TaskManager.Task::(_updateState) Task=3D`e97820bb-547d-4e7a-9249-ece94285bac8`::moving from state init -= > state preparing Thread-7814::INFO::2012-09-20 06:47:03,698::logUtils::37::dispatcher::(wrapper) Run and protect: inappropriateDevices(thiefId=3D'509e608c-e657-473a-b031-f0811da96bde') Thread-7814::INFO::2012-09-20 06:47:03,699::logUtils::39::dispatcher::(wrapper) Run and protect: inappropriateDevices, Return response: None Thread-7814::DEBUG::2012-09-20 06:47:03,699::task::1172::TaskManager.Task::(prepare) Task=3D`e97820bb-547d-4e7a-9249-ece94285bac8`::finished: None Thread-7814::DEBUG::2012-09-20 06:47:03,700::task::588::TaskManager.Task::(_updateState) Task=3D`e97820bb-547d-4e7a-9249-ece94285bac8`::moving from state prepar= ing -> state finished Thread-7814::DEBUG::2012-09-20 06:47:03,700::resourceManager::809::ResourceManager.Owner::(releaseAll)= Owner.releaseAll requests {} resources {} Thread-7814::DEBUG::2012-09-20 06:47:03,700::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-7814::DEBUG::2012-09-20 06:47:03,700::task::978::TaskManager.Task::(_decref) Task=3D`e97820bb-547d-4e7a-9249-ece94285bac8`::ref 0 aborting False Thread-7814::DEBUG::2012-09-20 06:47:03,700::libvirtvm::2080::vm.Vm::(deleteVm) vmId=3D`509e608c-e657-473a-b031-f0811da96bde`::Total desktops after des= troy of 509e608c-e657-473a-b031-f0811da96bde is 0 Thread-7814::DEBUG::2012-09-20 06:47:03,701::BindingXMLRPC::865::vds::(wrapper) return vmDestroy with {'status': {'message': 'Machine destroyed', 'code': 0}} Thread-481::DEBUG::2012-09-20 06:47:04,302::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/dd iflag=3Ddirect if=3D/dev/26187d25-bfcb-40c7-97d1-667705ad2223/metadata = bs=3D4096 count=3D1' (cwd None) Thread-481::DEBUG::2012-09-20 06:47:04,317::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err= > =3D '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.0008435= 51 s, 4.9 MB/s\n'; <rc> =3D 0 Dummy-1960::DEBUG::2012-09-20 06:47:05,239::__init__::1249::Storage.Misc.excCmd::(_log) 'dd if=3D/rhev/data-center/332694bb-364a-434e-b23f-5fef985d3cbd/mastersd/do= m_md/inbox iflag=3Ddirect,fullblock count=3D1 bs=3D1024000' (cwd None) Dummy-1960::DEBUG::2012-09-20 06:47:05,323::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err= > =3D '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0476= 578 s, 21.5 MB/s\n'; <rc> =3D 0 Thread-7815::DEBUG::2012-09-20 06:47:05,819::task::588::TaskManager.Task::(_updateState) Task=3D`ef5f39d0-241c-44b5-a771-da364468b498`::moving from state init -= > state preparing Thread-7815::INFO::2012-09-20 06:47:05,819::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=3DNone) Thread-7815::INFO::2012-09-20 06:47:05,820::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'26187d25-bfcb-40c7-97d1-667705ad2223': {'delay': '0.0156102180481', 'lastCheck': 1348123624.512314, 'code': 0,= 'valid': True}, '90104c3d-837b-47dd-8c82-dda92eec30d9': {'delay': '0.0011830329895', 'lastCheck': 1348123617.41074, 'code': 0, 'valid': True}} Thread-7815::DEBUG::2012-09-20 06:47:05,820::task::1172::TaskManager.Task::(prepare) Task=3D`ef5f39d0-241c-44b5-a771-da364468b498`::finished: {'26187d25-bfcb-40c7-97d1-667705ad2223': {'delay': '0.0156102180481', 'lastCheck': 1348123624.512314, 'code': 0, 'valid': True}, '90104c3d-837b-47dd-8c82-dda92eec30d9': {'delay': '0.0011830329895', 'lastCheck': 1348123617.41074, 'code': 0, 'valid': True}} Thread-7815::DEBUG::2012-09-20 06:47:05,820::task::588::TaskManager.Task::(_updateState) Task=3D`ef5f39d0-241c-44b5-a771-da364468b498`::moving from state prepar= ing -> state finished Thread-7815::DEBUG::2012-09-20 06:47:05,820::resourceManager::809::ResourceManager.Owner::(releaseAll)= Owner.releaseAll requests {} resources {} Thread-7815::DEBUG::2012-09-20 06:47:05,821::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-7815::DEBUG::2012-09-20 06:47:05,821::task::978::TaskManager.Task::(_decref) Task=3D`ef5f39d0-241c-44b5-a771-da364468b498`::ref 0 aborting False Dummy-1960::DEBUG::2012-09-20 06:47:07,332::__init__::1249::Storage.Misc.excCmd::(_log) 'dd if=3D/rhev/data-center/332694bb-364a-434e-b23f-5fef985d3cbd/mastersd/do= m_md/inbox iflag=3Ddirect,fullblock count=3D1 bs=3D1024000' (cwd None) Dummy-1960::DEBUG::2012-09-20 06:47:07,458::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err= > =3D '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0478= 973 s, 21.4 MB/s\n'; <rc> =3D 0 Dummy-1960::DEBUG::2012-09-20 06:47:09,502::__init__::1249::Storage.Misc.excCmd::(_log) 'dd if=3D/rhev/data-center/332694bb-364a-434e-b23f-5fef985d3cbd/mastersd/do= m_md/inbox iflag=3Ddirect,fullblock count=3D1 bs=3D1024000' (cwd None) Dummy-1960::DEBUG::2012-09-20 06:47:09,586::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err= > =3D '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0485= 543 s, 21.1 MB/s\n'; <rc> =3D 0 If I try to create new server I have the same error message. - - Dmitriy Pyryakov VimpelCom Ltd.= --0__=C9BBF0ECDFB7B2218f9e8a93df938690918cC9BBF0ECDFB7B221 Content-type: text/html; charset=US-ASCII Content-Disposition: inline Content-transfer-encoding: quoted-printable <html><body> Hello, Yesturday I broke my two Fedora 17= hosts. Today I install two ovirt nodes (f= irst - 2.5.0-2.0.fc17, second - 2.5.1-1.0.fc17). SPM on 2.5.0-2.0.fc17.= Now, I can't run any of my existin= g virtual machines. Exit message: unsupported configuration: spice secu= re channels set in XML configuration, but TLS is disabled in qemu.conf.= <ul style=3D"padding-left: 0pt"><b= r> engine.log:</ul> [root@admin ~]# tail -f -n 0 /var/= log/ovirt-engine/engine.log 2012-09-20 12:42:53,289 INFO [org= .ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand] (ajp--0.0.0.0= -8009-10) START, IsValidVDSCommand(storagePoolId =3D 332694bb-364a-434e= -b23f-5fef985d3cbd, ignoreFailoverLimit =3D false, compatabilityVersion= =3D null), log id: 7c90c641 2012-09-20 12:42:53,294 INFO [org= .ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand] (ajp--0.0.0.0= -8009-10) FINISH, IsValidVDSCommand, return: true, log id: 7c90c641</fo= nt> 2012-09-20 12:42:53,332 INFO [org= .ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (ajp--0.0.= 0.0-8009-10) START, IsVmDuringInitiatingVDSCommand(vmId =3D 509e608c-e6= 57-473a-b031-f0811da96bde), log id: 243c74f7 2012-09-20 12:42:53,334 INFO [org= .ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (ajp--0.0.= 0.0-8009-10) FINISH, IsVmDuringInitiatingVDSCommand, return: false, log= id: 243c74f7 2012-09-20 12:42:53,403 INFO [org= .ovirt.engine.core.bll.RunVmCommand] (pool-3-thread-50) [a58d974] Lock = Acquired to object EngineLock [exclusiveLocks=3D key: 509e608c-e657-473= a-b031-f0811da96bde value: VM , sharedLocks=3D ] 2012-09-20 12:42:53,415 INFO [org= .ovirt.engine.core.bll.RunVmCommand] (pool-3-thread-50) [a58d974] Runni= ng command: RunVmCommand internal: false. Entities affected : ID: 509e= 608c-e657-473a-b031-f0811da96bde Type: VM 2012-09-20 12:42:53,504 INFO [org= .ovirt.engine.core.vdsbroker.CreateVmVDSCommand] (pool-3-thread-50) [a5= 8d974] START, CreateVmVDSCommand(vdsId =3D 0a268762-02d7-11e2-b750-0011= 856cf23e, vmId=3D509e608c-e657-473a-b031-f0811da96bde, vm=3Dorg.ovirt.e= ngine.core.common.businessentities.VM@1911737b), log id: 77c0e559</font= > 2012-09-20 12:42:53,529 INFO [org= .ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] (pool-3-thread= -50) [a58d974] START, CreateVDSCommand(vdsId =3D 0a268762-02d7-11e2-b75= 0-0011856cf23e, vmId=3D509e608c-e657-473a-b031-f0811da96bde, vm=3Dorg.o= virt.engine.core.common.businessentities.VM@1911737b), log id: f48008f<= /font> 2012-09-20 12:42:53,602 INFO [org= .ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] (pool-3-thread= -50) [a58d974] org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSComma= nd spiceSslCipherSuite=3DDEFAULT,memSize=3D1024,kvmEnable=3Dtrue,smp=3D= 1,emulatedMachine=3Dpc-0.14,vmType=3Dkvm,keyboardLayout=3Den-us,pitRein= jection=3Dfalse,nice=3D0,display=3Dqxl,smpCoresPerSocket=3D1,spiceSecur= eChannels=3Dsmain,sinputs,scursor,splayback,srecord,sdisplay,displayNet= work=3Dovirtmgmt,timeOffset=3D-1,transparentHugePages=3Dtrue,vmId=3D509= e608c -e657-473a-b031-f0811da96bde,devices=3D= [Ljava.util.Map;@760db68c,acpiEnable=3Dtrue,vmName=3DCentOS6Thames,cpuT= ype=3DConroe,custom=3D{device_bb912edd-9790-43ff-a758-f1d9f20cb5f5devic= e_f5c86859-5ae9-4a37-9d34-2b9547609622device_20a11f26-6a39-415d-a7bf-95= 893b9c55b5=3DVmId=3D509e608c-e657-473a-b031-f0811da96bde,DeviceId=3D20a= 11f26-6a39-415d-a7bf-95893b9c55b5,Device=3Dunix,Type=3Dchannel,BootOrde= r=3D0,SpecParams=3D{},Address=3D{port=3D1, bus=3D0, controller=3D0, typ= e=3Dvirtio-serial},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3Dfals= e,alias=3D channel0, device_bb912edd-9790-43= ff-a758-f1d9f20cb5f5=3DVmId=3D509e608c-e657-473a-b031-f0811da96bde,Devi= ceId=3Dbb912edd-9790-43ff-a758-f1d9f20cb5f5,Device=3Dide,Type=3Dcontrol= ler,BootOrder=3D0,SpecParams=3D{},Address=3D{bus=3D0x00, domain=3D0x000= 0, type=3Dpci, slot=3D0x01, function=3D0x1},IsManaged=3Dfalse,IsPlugged= =3Dtrue,IsReadOnly=3Dfalse,alias=3Dide0, device_bb912edd-9790-43ff-a758= -f1d9f20cb5f5device_f5c86859-5ae9-4a37-9d34-2b9547609622=3DVmId=3D509e6= 08c-e657-473a-b031-f0811da96bde,DeviceId=3Df5c86859-5ae9-4a37-9d34-2b95= 47609622,Devic e=3Dvirtio-serial,Type=3Dcont= roller,BootOrder=3D0,SpecParams=3D{},Address=3D{bus=3D0x00, domain=3D0x= 0000, type=3Dpci, slot=3D0x04, function=3D0x0},IsManaged=3Dfalse,IsPlug= ged=3Dtrue,IsReadOnly=3Dfalse,alias=3Dvirtio-serial0, device_bb912edd-9= 790-43ff-a758-f1d9f20cb5f5device_f5c86859-5ae9-4a37-9d34-2b9547609622de= vice_20a11f26-6a39-415d-a7bf-95893b9c55b5device_21f255dc-9b3b-48d8-b8e4= -63c1635e269b=3DVmId=3D509e608c-e657-473a-b031-f0811da96bde,DeviceId=3D= 21f255dc-9b3b-48d8-b8e4-63c1635e269b,Device=3Dspicevmc,Type=3Dchannel,B= ootOrder=3D0,SpecP arams=3D{},Address=3D{por= t=3D2, bus=3D0, controller=3D0, type=3Dvirtio-serial},IsManaged=3Dfalse= ,IsPlugged=3Dtrue,IsReadOnly=3Dfalse,alias=3Dchannel1, device_bb912edd-= 9790-43ff-a758-f1d9f20cb5f5device_f5c86859-5ae9-4a37-9d34-2b9547609622d= evice_20a11f26-6a39-415d-a7bf-95893b9c55b5device_21f255dc-9b3b-48d8-b8e= 4-63c1635e269bdevice_d6c2c4d1-da6b-44fe-a5aa-508135c7fdfe=3DVmId=3D509e= 608c-e657-473a-b031-f0811da96bde,DeviceId=3Dd6c2c4d1-da6b-44fe-a5aa-508= 135c7fdfe,Device=3Dusb,Type=3Dcontroller,BootOrder=3D0,SpecParams=3D{},= Address=3D{bus=3D0x0 0, domain=3D0x0000, typ= e=3Dpci, slot=3D0x01, function=3D0x2},IsManaged=3Dfalse,IsPlugged=3Dtru= e,IsReadOnly=3Dfalse,alias=3Dusb0} 2012-09-20 12:42:53,625 INFO [org= .ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] (pool-3-thread= -50) [a58d974] FINISH, CreateVDSCommand, log id: f48008f 2012-09-20 12:42:53,659 INFO [org= .ovirt.engine.core.vdsbroker.CreateVmVDSCommand] (pool-3-thread-50) [a5= 8d974] IncreasePendingVms::CreateVmIncreasing vds hyper1.ovirt.com pend= ing vcpu count, now 1. Vm: CentOS6Thames 2012-09-20 12:42:53,671 INFO [org= .ovirt.engine.core.vdsbroker.CreateVmVDSCommand] (pool-3-thread-50) [a5= 8d974] FINISH, CreateVmVDSCommand, return: WaitForLaunch, log id: 77c0e= 559 2012-09-20 12:42:53,684 INFO [org= .ovirt.engine.core.bll.RunVmCommand] (pool-3-thread-50) [a58d974] Lock = freed to object EngineLock [exclusiveLocks=3D key: 509e608c-e657-473a-b= 031-f0811da96bde value: VM , sharedLocks=3D ] 2012-09-20 12:42:54,418 INFO [org= .ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (QuartzSchedu= ler_Worker-12) START, DestroyVDSCommand(vdsId =3D 0a268762-02d7-11e2-b7= 50-0011856cf23e, vmId=3D509e608c-e657-473a-b031-f0811da96bde, force=3Df= alse, secondsToWait=3D0, gracefully=3Dfalse), log id: 2f059be9<b= r> 2012-09-20 12:42:54,486 INFO [org= .ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (QuartzSchedu= ler_Worker-12) FINISH, DestroyVDSCommand, log id: 2f059be9 2012-09-20 12:42:54,520 INFO [org= .ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Wor= ker-12) Running on vds during rerun failed vm: null 2012-09-20 12:42:54,523 INFO [org= .ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Wor= ker-12) vm CentOS6Thames running in db and not running in vds - add to = rerun treatment. vds hyper1.ovirt.com 2012-09-20 12:42:54,536 ERROR [org= .ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Wor= ker-12) Rerun vm 509e608c-e657-473a-b031-f0811da96bde. Called from vds = hyper1.ovirt.com 2012-09-20 12:42:54,557 INFO [org= .ovirt.engine.core.vdsbroker.UpdateVdsDynamicDataVDSCommand] (pool-3-th= read-50) START, UpdateVdsDynamicDataVDSCommand(vdsId =3D 0a268762-02d7-= 11e2-b750-0011856cf23e, vdsDynamic=3Dorg.ovirt.engine.core.common.busin= essentities.VdsDynamic@db702e05), log id: 71c6e6a3 2012-09-20 12:42:54,564 INFO [org= .ovirt.engine.core.vdsbroker.UpdateVdsDynamicDataVDSCommand] (pool-3-th= read-50) FINISH, UpdateVdsDynamicDataVDSCommand, log id: 71c6e6a3</font= > 2012-09-20 12:42:54,584 INFO [org= .ovirt.engine.core.bll.RunVmCommand] (pool-3-thread-50) Lock Acquired t= o object EngineLock [exclusiveLocks=3D key: 509e608c-e657-473a-b031-f08= 11da96bde value: VM , sharedLocks=3D ] 2012-09-20 12:42:54,603 INFO [org= .ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand] (pool-3-threa= d-50) START, IsValidVDSCommand(storagePoolId =3D 332694bb-364a-434e-b23= f-5fef985d3cbd, ignoreFailoverLimit =3D false, compatabilityVersion =3D= null), log id: f1903fc 2012-09-20 12:42:54,614 INFO [org= .ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand] (pool-3-threa= d-50) FINISH, IsValidVDSCommand, return: true, log id: f1903fc<b= r> 2012-09-20 12:42:54,653 INFO [org= .ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (pool-3-th= read-50) START, IsVmDuringInitiatingVDSCommand(vmId =3D 509e608c-e657-4= 73a-b031-f0811da96bde), log id: 5b0d9779 2012-09-20 12:42:54,655 INFO [org= .ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (pool-3-th= read-50) FINISH, IsVmDuringInitiatingVDSCommand, return: false, log id:= 5b0d9779 2012-09-20 12:42:54,712 INFO [org= .ovirt.engine.core.bll.RunVmCommand] (pool-3-thread-50) Running command= : RunVmCommand internal: false. Entities affected : ID: 509e608c-e657-= 473a-b031-f0811da96bde Type: VM 2012-09-20 12:42:54,800 INFO [org= .ovirt.engine.core.vdsbroker.CreateVmVDSCommand] (pool-3-thread-50) STA= RT, CreateVmVDSCommand(vdsId =3D 9840e840-02db-11e2-a01a-0011856cf23e, = vmId=3D509e608c-e657-473a-b031-f0811da96bde, vm=3Dorg.ovirt.engine.core= .common.businessentities.VM@4432a01d), log id: 554a0742 2012-09-20 12:42:54,825 INFO [org= .ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] (pool-3-thread= -50) START, CreateVDSCommand(vdsId =3D 9840e840-02db-11e2-a01a-0011856c= f23e, vmId=3D509e608c-e657-473a-b031-f0811da96bde, vm=3Dorg.ovirt.engin= e.core.common.businessentities.VM@4432a01d), log id: 73615350<br= > 2012-09-20 12:42:54,912 INFO [org= .ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] (pool-3-thread= -50) org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand spiceSs= lCipherSuite=3DDEFAULT,memSize=3D1024,kvmEnable=3Dtrue,smp=3D1,emulated= Machine=3Dpc-0.14,vmType=3Dkvm,keyboardLayout=3Den-us,pitReinjection=3D= false,nice=3D0,display=3Dqxl,smpCoresPerSocket=3D1,spiceSecureChannels=3D= smain,sinputs,scursor,splayback,srecord,sdisplay,displayNetwork=3Dovirt= mgmt,timeOffset=3D-1,transparentHugePages=3Dtrue,vmId=3D509e608c-e657-4= 73a -b031-f0811da96bde,devices=3D[Ljava.util= .Map;@41d42882,acpiEnable=3Dtrue,vmName=3DCentOS6Thames,cpuType=3DConro= e,custom=3D{device_bb912edd-9790-43ff-a758-f1d9f20cb5f5device_f5c86859-= 5ae9-4a37-9d34-2b9547609622device_20a11f26-6a39-415d-a7bf-95893b9c55b5=3D= VmId=3D509e608c-e657-473a-b031-f0811da96bde,DeviceId=3D20a11f26-6a39-41= 5d-a7bf-95893b9c55b5,Device=3Dunix,Type=3Dchannel,BootOrder=3D0,SpecPar= ams=3D{},Address=3D{port=3D1, bus=3D0, controller=3D0, type=3Dvirtio-se= rial},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3Dfalse,alias=3Dcha= nnel0, device_bb912edd-9790-43ff-a758-f1d9f= 20cb5f5=3DVmId=3D509e608c-e657-473a-b031-f0811da96bde,DeviceId=3Dbb912e= dd-9790-43ff-a758-f1d9f20cb5f5,Device=3Dide,Type=3Dcontroller,BootOrder= =3D0,SpecParams=3D{},Address=3D{bus=3D0x00, domain=3D0x0000, type=3Dpci= , slot=3D0x01, function=3D0x1},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsRea= dOnly=3Dfalse,alias=3Dide0, device_bb912edd-9790-43ff-a758-f1d9f20cb5f5= device_f5c86859-5ae9-4a37-9d34-2b9547609622=3DVmId=3D509e608c-e657-473a= -b031-f0811da96bde,DeviceId=3Df5c86859-5ae9-4a37-9d34-2b9547609622,Devi= ce=3Dvirtio-s erial,Type=3Dcontroller,BootOr= der=3D0,SpecParams=3D{},Address=3D{bus=3D0x00, domain=3D0x0000, type=3D= pci, slot=3D0x04, function=3D0x0},IsManaged=3Dfalse,IsPlugged=3Dtrue,Is= ReadOnly=3Dfalse,alias=3Dvirtio-serial0, device_bb912edd-9790-43ff-a758= -f1d9f20cb5f5device_f5c86859-5ae9-4a37-9d34-2b9547609622device_20a11f26= -6a39-415d-a7bf-95893b9c55b5device_21f255dc-9b3b-48d8-b8e4-63c1635e269b= =3DVmId=3D509e608c-e657-473a-b031-f0811da96bde,DeviceId=3D21f255dc-9b3b= -48d8-b8e4-63c1635e269b,Device=3Dspicevmc,Type=3Dchannel,BootOrder=3D0,= SpecParams=3D{},A ddress=3D{port=3D2, bus=3D= 0, controller=3D0, type=3Dvirtio-serial},IsManaged=3Dfalse,IsPlugged=3D= true,IsReadOnly=3Dfalse,alias=3Dchannel1, device_bb912edd-9790-43ff-a75= 8-f1d9f20cb5f5device_f5c86859-5ae9-4a37-9d34-2b9547609622device_20a11f2= 6-6a39-415d-a7bf-95893b9c55b5device_21f255dc-9b3b-48d8-b8e4-63c1635e269= bdevice_d6c2c4d1-da6b-44fe-a5aa-508135c7fdfe=3DVmId=3D509e608c-e657-473= a-b031-f0811da96bde,DeviceId=3Dd6c2c4d1-da6b-44fe-a5aa-508135c7fdfe,Dev= ice=3Dusb,Type=3Dcontroller,BootOrder=3D0,SpecParams=3D{},Address=3D{bu= s=3D0x00, domain=3D 0x0000, type=3Dpci, slot= =3D0x01, function=3D0x2},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3D= false,alias=3Dusb0} 2012-09-20 12:42:54,982 INFO [org= .ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] (pool-3-thread= -50) FINISH, CreateVDSCommand, log id: 73615350 2012-09-20 12:42:55,004 INFO [org= .ovirt.engine.core.vdsbroker.CreateVmVDSCommand] (pool-3-thread-50) Inc= reasePendingVms::CreateVmIncreasing vds hyper2.ovirt.com pending vcpu c= ount, now 1. Vm: CentOS6Thames 2012-09-20 12:42:55,012 INFO [org= .ovirt.engine.core.vdsbroker.CreateVmVDSCommand] (pool-3-thread-50) FIN= ISH, CreateVmVDSCommand, return: WaitForLaunch, log id: 554a0742= 2012-09-20 12:42:55,022 INFO [org= .ovirt.engine.core.bll.RunVmCommand] (pool-3-thread-50) Lock freed to o= bject EngineLock [exclusiveLocks=3D key: 509e608c-e657-473a-b031-f0811d= a96bde value: VM , sharedLocks=3D ] 2012-09-20 12:42:56,434 INFO [org= .ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (QuartzSchedu= ler_Worker-32) START, DestroyVDSCommand(vdsId =3D 9840e840-02db-11e2-a0= 1a-0011856cf23e, vmId=3D509e608c-e657-473a-b031-f0811da96bde, force=3Df= alse, secondsToWait=3D0, gracefully=3Dfalse), log id: 6b44f6c9<b= r> 2012-09-20 12:42:56,497 INFO [org= .ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (QuartzSchedu= ler_Worker-32) FINISH, DestroyVDSCommand, log id: 6b44f6c9 2012-09-20 12:42:56,532 INFO [org= .ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Wor= ker-32) Running on vds during rerun failed vm: null 2012-09-20 12:42:56,535 INFO [org= .ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Wor= ker-32) vm CentOS6Thames running in db and not running in vds - add to = rerun treatment. vds hyper2.ovirt.com 2012-09-20 12:42:56,548 ERROR [org= .ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Wor= ker-32) Rerun vm 509e608c-e657-473a-b031-f0811da96bde. Called from vds = hyper2.ovirt.com 2012-09-20 12:42:56,582 INFO [org= .ovirt.engine.core.vdsbroker.UpdateVdsDynamicDataVDSCommand] (pool-3-th= read-50) START, UpdateVdsDynamicDataVDSCommand(vdsId =3D 9840e840-02db-= 11e2-a01a-0011856cf23e, vdsDynamic=3Dorg.ovirt.engine.core.common.busin= essentities.VdsDynamic@5f1dd7c7), log id: 2a191f9e 2012-09-20 12:42:56,596 INFO [org= .ovirt.engine.core.vdsbroker.UpdateVdsDynamicDataVDSCommand] (pool-3-th= read-50) FINISH, UpdateVdsDynamicDataVDSCommand, log id: 2a191f9e</font= > 2012-09-20 12:42:56,616 INFO [org= .ovirt.engine.core.bll.RunVmCommand] (pool-3-thread-50) Lock Acquired t= o object EngineLock [exclusiveLocks=3D key: 509e608c-e657-473a-b031-f08= 11da96bde value: VM , sharedLocks=3D ] 2012-09-20 12:42:56,632 INFO [org= .ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand] (pool-3-threa= d-50) START, IsValidVDSCommand(storagePoolId =3D 332694bb-364a-434e-b23= f-5fef985d3cbd, ignoreFailoverLimit =3D false, compatabilityVersion =3D= null), log id: 4629f11d 2012-09-20 12:42:56,636 INFO [org= .ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand] (pool-3-threa= d-50) FINISH, IsValidVDSCommand, return: true, log id: 4629f11d<= br> 2012-09-20 12:42:56,672 INFO [org= .ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (pool-3-th= read-50) START, IsVmDuringInitiatingVDSCommand(vmId =3D 509e608c-e657-4= 73a-b031-f0811da96bde), log id: f3a60e 2012-09-20 12:42:56,675 INFO [org= .ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (pool-3-th= read-50) FINISH, IsVmDuringInitiatingVDSCommand, return: false, log id:= f3a60e 2012-09-20 12:42:56,713 WARN [org= .ovirt.engine.core.bll.RunVmCommand] (pool-3-thread-50) CanDoAction of = action RunVm failed. Reasons:VAR__ACTION__RUN,VAR__TYPE__VM,VAR__ACTION= __RUN,VAR__TYPE__VM,VAR__ACTION__RUN,VAR__TYPE__VM,VAR__ACTION__RUN,VAR= __TYPE__VM,ACTION_TYPE_FAILED_VDS_VM_CLUSTER 2012-09-20 12:42:56,717 INFO [org= .ovirt.engine.core.bll.RunVmCommand] (pool-3-thread-50) Lock freed to o= bject EngineLock [exclusiveLocks=3D key: 509e608c-e657-473a-b031-f0811d= a96bde value: VM , sharedLocks=3D ] vdsm.log: Dummy-1960::DEBUG::2012-09-20 06:4= 6:58,959::__init__::1249::Storage.Misc.excCmd::(_log) 'dd if=3D/rhev/da= ta-center/332694bb-364a-434e-b23f-5fef985d3cbd/mastersd/dom_md/inbox if= lag=3Ddirect,fullblock count=3D1 bs=3D1024000' (cwd None) Dummy-1960::DEBUG::2012-09-20 06:4= 6:59,043::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err&= gt; =3D '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied= , 0.0488089 s, 21.0 MB/s\n'; <rc> =3D 0 Dummy-1960::DEBUG::2012-09-20 06:4= 7:01,053::__init__::1249::Storage.Misc.excCmd::(_log) 'dd if=3D/rhev/da= ta-center/332694bb-364a-434e-b23f-5fef985d3cbd/mastersd/dom_md/inbox if= lag=3Ddirect,fullblock count=3D1 bs=3D1024000' (cwd None) Dummy-1960::DEBUG::2012-09-20 06:4= 7:01,136::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err&= gt; =3D '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied= , 0.0477826 s, 21.4 MB/s\n'; <rc> =3D 0 Thread-7807::DEBUG::2012-09-20 06:= 47:01,991::BindingXMLRPC::859::vds::(wrapper) client [192.168.10.10]::c= all vmCreate with ({'custom': {'device_bb912edd-9790-43ff-a758-f1d9f20c= b5f5device_f5c86859-5ae9-4a37-9d34-2b9547609622device_20a11f26-6a39-415= d-a7bf-95893b9c55b5device_21f255dc-9b3b-48d8-b8e4-63c1635e269bdevice_d6= c2c4d1-da6b-44fe-a5aa-508135c7fdfe': 'VmId=3D509e608c-e657-473a-b031-f0= 811da96bde,DeviceId=3Dd6c2c4d1-da6b-44fe-a5aa-508135c7fdfe,Device=3Dusb= ,Type=3Dcontroller,BootOrder=3D0,SpecParams=3D{},Address=3D{bus=3D0x00,= domain=3D0x0000, type=3Dpci, slot=3D0x01, function=3D0x2},IsManaged=3D= false,IsPlugged=3Dtrue,IsReadOnly=3Dfalse,alias=3Dusb0', 'device_bb912e= dd-9790-43ff-a758-f1d9f20cb5f5device_f5c86859-5ae9-4a37-9d34-2b95476096= 22device_20a11f26-6a39-415d-a7bf-95893b9c55b5device_21f255dc-9b3b-48d8-= b8e4-63c1635e269b': 'VmId=3D509e608c-e657-473a-b031-f0811da96bde,Device= Id=3D21f255dc-9b3b-48d8-b8e4-63c1635e269b,Device=3Dspicevmc,Type=3Dchan= nel,BootOrder=3D0,SpecParams=3D{},Address=3D{port=3D2, bus=3D0, control= ler=3D0, type=3Dvirtio-serial},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsRea= dOnly=3Dfalse,alias=3Dchannel1', 'device_bb912edd-9790-43ff-a758-f1d9f2= 0cb5f5device_f5c86859-5ae9-4a37-9d34-2b9547609622': 'VmId=3D509e608c-e6= 57-473a-b031-f0811da96bde,DeviceId=3Df5c86859-5ae9-4a37-9d34-2b95476096= 22,Device=3Dvirtio-serial,Type=3Dcontroller,BootOrder=3D0,SpecParams=3D= {},Address=3D{bus=3D0x00, domain=3D0x0000, type=3Dpci, slot=3D0x04, fun= ction=3D0x0},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3Dfalse,alia= s=3Dvirtio-serial0', 'device_bb912edd-9790-43ff-a758-f1d9f20cb5f5device= _f5c86859-5ae9-4a37-9d34-2b9547609622device_20a11f26-6a39-415d-a7bf-958= 93b9c55b5': 'VmId=3D509e608c-e657-473a-b031-f0811da96bde,DeviceId=3D20a= 11f26-6a39-415d-a7bf-95893b9c55b5,Device=3Dunix,Type=3Dchannel,BootOrde= r=3D0,SpecParams=3D{},Address=3D{port=3D1, bus=3D0, controller=3D0, typ= e=3Dvirtio-serial},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3Dfals= e,alias=3Dchannel0', 'device_bb912edd-9790-43ff-a758-f1d9f20cb5f5': 'Vm= Id=3D509e608c-e657-473a-b031-f0811da96bde,DeviceId=3Dbb912edd-9790-43ff= -a758-f1d9f20cb5f5,Device=3Dide,Type=3Dcontroller,BootOrder=3D0,SpecPar= ams=3D{},Address=3D{bus=3D0x00, domain=3D0x0000, type=3Dpci, slot=3D0x0= 1, function=3D0x1},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3Dfals= e,alias=3Dide0'}, 'keyboardLayout': 'en-us', 'kvmEnable': 'true', 'pitR= einjection': 'false', 'acpiEnable': 'true', 'emulatedMachine': 'pc-0.14= ', 'displayNetwork': 'ovirtmgmt', 'vmId': '509e608c-e657-473a-b031-f081= 1da96bde', 'devices': [{'device': 'qxl', 'specParams': {'vram': '65536'= }, 'type': 'video', 'deviceId': '20c037f2-11e5-49a5-ace7-741023ec0ce9',= 'address': {'bus': '0x00', ' slot': '0x02', ' domain': '0x0000', ' typ= e': 'pci', ' function': '0x0'}}, {'index': '2', 'iface': 'ide', 'specPa= rams': {'path': ''}, 'readonly': 'true', 'deviceId': '1ed8a73e-be34-482= 9-a7e3-151a7a2efedc', 'address': {' controller': '0', ' target': '0', '= unit': '0', ' bus': '1', ' type': 'drive'}, 'device': 'cdrom', 'path': = '', 'type': 'disk'}, {'iface': 'virtio', 'format': 'cow', 'type': 'disk= ', 'poolID': '332694bb-364a-434e-b23f-5fef985d3cbd', 'volumeID': 'f184e= cd1-0001-4739-af71-250b412345d6', 'imageID': '0a7013db-68fd-4c42-bc2e-c= c8d7a05ca18', 'specParams': {}, 'readonly': 'false', 'domainID': '26187= d25-bfcb-40c7-97d1-667705ad2223', 'deviceId': '0a7013db-68fd-4c42-bc2e-= cc8d7a05ca18', 'address': {'bus': '0x00', ' slot': '0x05', ' domain': '= 0x0000', ' type': 'pci', ' function': '0x0'}, 'device': 'disk', 'shared= ': 'false', 'propagateErrors': 'off', 'optional': 'false'}, {'nicModel'= : 'pv', 'macAddr': '00:1a:4a:a8:0a:00', 'network': 'ovirtmgmt', 'specPa= rams': {}, 'deviceId': '7392f689-2ba3-4243-9629-96b192b102a5', 'address= ': {'bus': '0x00', ' slot': '0x03', ' domain': '0x0000', ' type': 'pci'= , ' function': '0x0'}, 'device': 'bridge', 'type': 'interface'}, {'devi= ce': 'usb', 'specParams': {}, 'type': 'controller', 'deviceId': 'd6c2c4= d1-da6b-44fe-a5aa-508135c7fdfe', 'address': {'bus': '0x00', ' slot': '0= x01', ' domain': '0x0000', ' type': 'pci', ' function': '0x2'}}, {'devi= ce': 'memballoon', 'specParams': {'model': 'virtio'}, 'type': 'balloon'= , 'deviceId': 'babd73a4-de64-4dce-91b9-e64c5b46c444'}], 'smp': '1', 'vm= Type': 'kvm', 'timeOffset': ' -1', 'memSize': 1024, 'spiceSslCip= herSuite': 'DEFAULT', 'cpuType': 'Conroe', 'spiceSecureChannels': 'smai= n,sinputs,scursor,splayback,srecord,sdisplay', 'smpCoresPerSocket': '1'= , 'vmName': 'CentOS6Thames', 'display': 'qxl', 'transparentHugePages': = 'true', 'nice': '0'},) {} Thread-7807::INFO::2012-09-20 06:4= 7:01,992::API::228::vds::(create) vmContainerLock acquired by vm 509e60= 8c-e657-473a-b031-f0811da96bde Thread-7808::DEBUG::2012-09-20 06:= 47:01,996::vm::564::vm.Vm::(_startUnderlyingVm) vmId=3D`509e608c-e657-4= 73a-b031-f0811da96bde`::Start Thread-7807::DEBUG::2012-09-20 06:= 47:01,996::API::244::vds::(create) Total desktops after creation of 509= e608c-e657-473a-b031-f0811da96bde is 1 Thread-7808::DEBUG::2012-09-20 06:= 47:01,997::vm::568::vm.Vm::(_startUnderlyingVm) vmId=3D`509e608c-e657-4= 73a-b031-f0811da96bde`::_ongoingCreations acquired Thread-7807::DEBUG::2012-09-20 06:= 47:01,997::BindingXMLRPC::865::vds::(wrapper) return vmCreate with {'st= atus': {'message': 'Done', 'code': 0}, 'vmList': {'status': 'WaitForLau= nch', 'acpiEnable': 'true', 'emulatedMachine': 'pc-0.14', 'vmId': '509e= 608c-e657-473a-b031-f0811da96bde', 'pid': '0', 'timeOffset': '-1', 'dis= playPort': '-1', 'displaySecurePort': '-1', 'spiceSslCipherSuite': 'DEF= AULT', 'cpuType': 'Conroe', 'custom': {'device_bb912edd-9790-43ff-a758-= f1d9f20cb5f5device_f5c86859-5ae9-4a37-9d34-2b9547609622device_20a11f26-= 6a39-415d-a7bf-95893b9c55b5device_21f255dc-9b3b-48d8-b8e4-63c1635e269bd= evice_d6c2c4d1-da6b-44fe-a5aa-508135c7fdfe': 'VmId=3D509e608c-e657-473a= -b031-f0811da96bde,DeviceId=3Dd6c2c4d1-da6b-44fe-a5aa-508135c7fdfe,Devi= ce=3Dusb,Type=3Dcontroller,BootOrder=3D0,SpecParams=3D{},Address=3D{bus= =3D0x00, domain=3D0x0000, type=3Dpci, slot=3D0x01, function=3D0x2},IsMa= naged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3Dfalse,alias=3Dusb0', 'devic= e_bb912edd-9790-43ff-a758-f1d9f20cb5f5device_f5c86859-5ae9-4a37-9d34-2b= 9547609622device_20a11f26-6a39-415d-a7bf-95893b9c55b5device_21f255dc-9b= 3b-48d8-b8e4-63c1635e269b': 'VmId=3D509e608c-e657-473a-b031-f0811da96bd= e,DeviceId=3D21f255dc-9b3b-48d8-b8e4-63c1635e269b,Device=3Dspicevmc,Typ= e=3Dchannel,BootOrder=3D0,SpecParams=3D{},Address=3D{port=3D2, bus=3D0,= controller=3D0, type=3Dvirtio-serial},IsManaged=3Dfalse,IsPlugged=3Dtr= ue,IsReadOnly=3Dfalse,alias=3Dchannel1', 'device_bb912edd-9790-43ff-a75= 8-f1d9f20cb5f5device_f5c86859-5ae9-4a37-9d34-2b9547609622': 'VmId=3D509= e608c-e657-473a-b031-f0811da96bde,DeviceId=3Df5c86859-5ae9-4a37-9d34-2b= 9547609622,Device=3Dvirtio-serial,Type=3Dcontroller,BootOrder=3D0,SpecP= arams=3D{},Address=3D{bus=3D0x00, domain=3D0x0000, type=3Dpci, slot=3D0= x04, function=3D0x0},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3Dfa= lse,alias=3Dvirtio-serial0', 'device_bb912edd-9790-43ff-a758-f1d9f20cb5= f5device_f5c86859-5ae9-4a37-9d34-2b9547609622device_20a11f26-6a39-415d-= a7bf-95893b9c55b5': 'VmId=3D509e608c-e657-473a-b031-f0811da96bde,Device= Id=3D20a11f26-6a39-415d-a7bf-95893b9c55b5,Device=3Dunix,Type=3Dchannel,= BootOrder=3D0,SpecParams=3D{},Address=3D{port=3D1, bus=3D0, controller=3D= 0, type=3Dvirtio-serial},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3D= false,alias=3Dchannel0', 'device_bb912edd-9790-43ff-a758-f1d9f20cb5f5':= 'VmId=3D509e608c-e657-473a-b031-f0811da96bde,DeviceId=3Dbb912edd-9790-= 43ff-a758-f1d9f20cb5f5,Device=3Dide,Type=3Dcontroller,BootOrder=3D0,Spe= cParams=3D{},Address=3D{bus=3D0x00, domain=3D0x0000, type=3Dpci, slot=3D= 0x01, function=3D0x1},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3Df= alse,alias=3Dide0'}, 'clientIp': '', 'nicModel': 'rtl8139,pv', 'keyboar= dLayout': 'en-us', 'kvmEnable': 'true', 'pitReinjection': 'false', 'tra= nsparentHugePages': 'true', 'displayNetwork': 'ovirtmgmt', 'devices': [= {'device': 'qxl', 'specParams': {'vram': '65536'}, 'type': 'video', 'de= viceId': '20c037f2-11e5-49a5-ace7-741023ec0ce9', 'address': {'bus': '0x= 00', ' slot': '0x02', ' domain': '0x0000', ' type': 'pci', ' function':= '0x0'}}, {'index': '2', 'iface': 'ide', 'specParams': {'path': ''}, 'r= eadonly': 'true', 'deviceId': '1ed8a73e-be34-4829-a7e3-151a7a2efedc', '= address': {' controller': '0', ' target': '0', 'unit': '0', ' bus': '1'= , ' type': 'drive'}, 'device': 'cdrom', 'path': '', 'type': 'disk'}, {'= iface': 'virtio', 'format': 'cow', 'type': 'disk', 'poolID': '332694bb-= 364a-434e-b23f-5fef985d3cbd', 'volumeID': 'f184ecd1-0001-4739-af71-250b= 412345d6', 'imageID': '0a7013db-68fd-4c42-bc2e-cc8d7a05ca18', 'specPara= ms': {}, 'readonly': 'false', 'domainID': '26187d25-bfcb-40c7-97d1-6677= 05ad2223', 'deviceId': '0a7013db-68fd-4c42-bc2e-cc8d7a05ca18', 'address= ': {'bus': '0x00', ' slot': '0x05', ' domain': '0x0000', ' type': 'pci'= , ' function': '0x0'}, 'device': 'disk', 'shared': 'false', 'propagateE= rrors': 'off', 'optional': 'false'}, {'nicModel': 'pv', 'macAddr': '00:= 1a:4a:a8:0a:00', 'network': 'ovirtmgmt', 'specParams': {}, 'deviceId': = '7392f689-2ba3-4243-9629-96b192b102a5', 'address': {'bus': '0x00', ' sl= ot': '0x03', ' domain': '0x0000', ' type': 'pci', ' function': '0x0'}, = 'device': 'bridge', 'type': 'interface'}, {'device': 'usb', 'specParams= ': {}, 'type': 'controller', 'deviceId': 'd6c2c4d1-da6b-44fe-a5aa-50813= 5c7fdfe', 'address': {'b us': '0x00', ' slot': '0x01', ' do= main': '0x0000', ' type': 'pci', ' function': '0x2'}}, {'device': 'memb= alloon', 'specParams': {'model': 'virtio'}, 'type': 'balloon', 'deviceI= d': 'babd73a4-de64-4dce-91b9-e64c5b46c444'}], 'smp': '1', 'vmType': 'kv= m', 'memSize': 1024, 'displayIp': '192.168.10.13', 'spiceSecureChannels= ': 'smain,sinputs,scursor,splayback,srecord,sdisplay', 'smpCoresPerSock= et': '1', 'vmName': 'CentOS6Thames', 'display': 'qxl', 'nice': '0'}}</f= ont> Thread-7808::INFO::2012-09-20 06:4= 7:01,997::libvirtvm::1285::vm.Vm::(_run) vmId=3D`509e608c-e657-473a-b03= 1-f0811da96bde`::VM wrapper has started Thread-7808::DEBUG::2012-09-20 06:= 47:02,000::task::588::TaskManager.Task::(_updateState) Task=3D`b6ef82b2= -2986-4b7b-95ba-d5f3cac8ad31`::moving from state init -> state prepa= ring Thread-7808::INFO::2012-09-20 06:4= 7:02,001::logUtils::37::dispatcher::(wrapper) Run and protect: getVolum= eSize(sdUUID=3D'26187d25-bfcb-40c7-97d1-667705ad2223', spUUID=3D'332694= bb-364a-434e-b23f-5fef985d3cbd', imgUUID=3D'0a7013db-68fd-4c42-bc2e-cc8= d7a05ca18', volUUID=3D'f184ecd1-0001-4739-af71-250b412345d6', options=3D= None) Thread-7808::DEBUG::2012-09-20 06:= 47:02,001::resourceManager::175::ResourceManager.Request::(__init__) Re= sName=3D`Storage.26187d25-bfcb-40c7-97d1-667705ad2223`ReqID=3D`83dac2e0= -3d55-4ef6-abf3-7b2561814ab4`::Request was made in '/usr/share/vdsm/sto= rage/resourceManager.py' line '485' at 'registerResource' Thread-7808::DEBUG::2012-09-20 06:= 47:02,002::resourceManager::486::ResourceManager::(registerResource) Tr= ying to register resource 'Storage.26187d25-bfcb-40c7-97d1-667705ad2223= ' for lock type 'shared' Thread-7808::DEBUG::2012-09-20 06:= 47:02,002::resourceManager::528::ResourceManager::(registerResource) Re= source 'Storage.26187d25-bfcb-40c7-97d1-667705ad2223' is free. Now lock= ing as 'shared' (1 active user) Thread-7808::DEBUG::2012-09-20 06:= 47:02,002::resourceManager::212::ResourceManager.Request::(grant) ResNa= me=3D`Storage.26187d25-bfcb-40c7-97d1-667705ad2223`ReqID=3D`83dac2e0-3d= 55-4ef6-abf3-7b2561814ab4`::Granted request Thread-7808::DEBUG::2012-09-20 06:= 47:02,003::task::817::TaskManager.Task::(resourceAcquired) Task=3D`b6ef= 82b2-2986-4b7b-95ba-d5f3cac8ad31`::_resourcesAcquired: Storage.26187d25= -bfcb-40c7-97d1-667705ad2223 (shared) Thread-7808::DEBUG::2012-09-20 06:= 47:02,003::task::978::TaskManager.Task::(_decref) Task=3D`b6ef82b2-2986= -4b7b-95ba-d5f3cac8ad31`::ref 1 aborting False Thread-7808::INFO::2012-09-20 06:4= 7:02,004::logUtils::39::dispatcher::(wrapper) Run and protect: getVolum= eSize, Return response: {'truesize': '13958643712', 'apparentsize': '13= 958643712'} Thread-7808::DEBUG::2012-09-20 06:= 47:02,004::task::1172::TaskManager.Task::(prepare) Task=3D`b6ef82b2-298= 6-4b7b-95ba-d5f3cac8ad31`::finished: {'truesize': '13958643712', 'appar= entsize': '13958643712'} Thread-7808::DEBUG::2012-09-20 06:= 47:02,004::task::588::TaskManager.Task::(_updateState) Task=3D`b6ef82b2= -2986-4b7b-95ba-d5f3cac8ad31`::moving from state preparing -> state = finished Thread-7808::DEBUG::2012-09-20 06:= 47:02,004::resourceManager::809::ResourceManager.Owner::(releaseAll) Ow= ner.releaseAll requests {} resources {'Storage.26187d25-bfcb-40c7-97d1-= 667705ad2223': < ResourceRef 'Storage.26187d25-bfcb-40c7-97d1-667705= ad2223', isValid: 'True' obj: 'None'>} Thread-7808::DEBUG::2012-09-20 06:= 47:02,004::resourceManager::844::ResourceManager.Owner::(cancelAll) Own= er.cancelAll requests {} Thread-7808::DEBUG::2012-09-20 06:= 47:02,005::resourceManager::538::ResourceManager::(releaseResource) Try= ing to release resource 'Storage.26187d25-bfcb-40c7-97d1-667705ad2223'<= /font> Thread-7808::DEBUG::2012-09-20 06:= 47:02,005::resourceManager::553::ResourceManager::(releaseResource) Rel= eased resource 'Storage.26187d25-bfcb-40c7-97d1-667705ad2223' (0 active= users) Thread-7808::DEBUG::2012-09-20 06:= 47:02,005::resourceManager::558::ResourceManager::(releaseResource) Res= ource 'Storage.26187d25-bfcb-40c7-97d1-667705ad2223' is free, finding o= ut if anyone is waiting for it. Thread-7808::DEBUG::2012-09-20 06:= 47:02,005::resourceManager::565::ResourceManager::(releaseResource) No = one is waiting for resource 'Storage.26187d25-bfcb-40c7-97d1-667705ad22= 23', Clearing records. Thread-7808::DEBUG::2012-09-20 06:= 47:02,005::task::978::TaskManager.Task::(_decref) Task=3D`b6ef82b2-2986= -4b7b-95ba-d5f3cac8ad31`::ref 0 aborting False Thread-7808::INFO::2012-09-20 06:4= 7:02,006::clientIF::274::vds::(prepareVolumePath) prepared volume path:= Thread-7808::DEBUG::2012-09-20 06:= 47:02,006::task::588::TaskManager.Task::(_updateState) Task=3D`83579cfe= -4384-4b76-8bb0-979ed2b60739`::moving from state init -> state prepa= ring Thread-7808::INFO::2012-09-20 06:4= 7:02,006::logUtils::37::dispatcher::(wrapper) Run and protect: prepareI= mage(sdUUID=3D'26187d25-bfcb-40c7-97d1-667705ad2223', spUUID=3D'332694b= b-364a-434e-b23f-5fef985d3cbd', imgUUID=3D'0a7013db-68fd-4c42-bc2e-cc8d= 7a05ca18', volUUID=3D'f184ecd1-0001-4739-af71-250b412345d6') = Thread-7808::DEBUG::2012-09-20 06:= 47:02,007::resourceManager::175::ResourceManager.Request::(__init__) Re= sName=3D`Storage.26187d25-bfcb-40c7-97d1-667705ad2223`ReqID=3D`c22e6209= -b86d-448c-8884-372ce9a589c4`::Request was made in '/usr/share/vdsm/sto= rage/resourceManager.py' line '485' at 'registerResource' Thread-7808::DEBUG::2012-09-20 06:= 47:02,007::resourceManager::486::ResourceManager::(registerResource) Tr= ying to register resource 'Storage.26187d25-bfcb-40c7-97d1-667705ad2223= ' for lock type 'shared' Thread-7808::DEBUG::2012-09-20 06:= 47:02,007::resourceManager::528::ResourceManager::(registerResource) Re= source 'Storage.26187d25-bfcb-40c7-97d1-667705ad2223' is free. Now lock= ing as 'shared' (1 active user) Thread-7808::DEBUG::2012-09-20 06:= 47:02,007::resourceManager::212::ResourceManager.Request::(grant) ResNa= me=3D`Storage.26187d25-bfcb-40c7-97d1-667705ad2223`ReqID=3D`c22e6209-b8= 6d-448c-8884-372ce9a589c4`::Granted request Thread-7808::DEBUG::2012-09-20 06:= 47:02,008::task::817::TaskManager.Task::(resourceAcquired) Task=3D`8357= 9cfe-4384-4b76-8bb0-979ed2b60739`::_resourcesAcquired: Storage.26187d25= -bfcb-40c7-97d1-667705ad2223 (shared) Thread-7808::DEBUG::2012-09-20 06:= 47:02,008::task::978::TaskManager.Task::(_decref) Task=3D`83579cfe-4384= -4b76-8bb0-979ed2b60739`::ref 1 aborting False Thread-7808::DEBUG::2012-09-20 06:= 47:02,008::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/dd ifl= ag=3Ddirect skip=3D4 bs=3D512 if=3D/dev/26187d25-bfcb-40c7-97d1-667705a= d2223/metadata count=3D1' (cwd None) Thread-7808::DEBUG::2012-09-20 06:= 47:02,023::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err= > =3D '1+0 records in\n1+0 records out\n512 bytes (512 B) copied, 0.= 000766795 s, 668 kB/s\n'; <rc> =3D 0 Thread-7808::DEBUG::2012-09-20 06:= 47:02,023::misc::314::Storage.Misc::(validateDDBytes) err: ['1+0 record= s in', '1+0 records out', '512 bytes (512 B) copied, 0.000766795 s, 668= kB/s'], size: 512 Thread-7808::INFO::2012-09-20 06:4= 7:02,023::image::357::Storage.Image::(getChain) sdUUID=3D26187d25-bfcb-= 40c7-97d1-667705ad2223 imgUUID=3D0a7013db-68fd-4c42-bc2e-cc8d7a05ca18 c= hain=3D<storage.blockVolume.BlockVolume instance at 0x7ff9fc0feb90></fo= nt> Thread-7808::INFO::2012-09-20 06:4= 7:02,024::logUtils::39::dispatcher::(wrapper) Run and protect: prepareI= mage, Return response: {'path': '/rhev/data-center/332694bb-364a-434e-b= 23f-5fef985d3cbd/26187d25-bfcb-40c7-97d1-667705ad2223/images/0a7013db-6= 8fd-4c42-bc2e-cc8d7a05ca18/f184ecd1-0001-4739-af71-250b412345d6', 'chai= n': [{'path': '/rhev/data-center/332694bb-364a-434e-b23f-5fef985d3cbd/2= 6187d25-bfcb-40c7-97d1-667705ad2223/images/0a7013db-68fd-4c42-bc2e-cc8d= 7a05ca18/f184ecd1-0001-4739-af71-250b412345d6', 'domainID': '26187d25-b= fcb-40c7-97d1-667705ad2223', 'volumeID': 'f184ecd1-0001-4739-af71-250b4= 12345d6', 'imageID': '0a7013db-68fd-4c42-bc2e-cc8d7a05ca18'}]}<b= r> Thread-7808::DEBUG::2012-09-20 06:= 47:02,024::task::1172::TaskManager.Task::(prepare) Task=3D`83579cfe-438= 4-4b76-8bb0-979ed2b60739`::finished: {'path': '/rhev/data-center/332694= bb-364a-434e-b23f-5fef985d3cbd/26187d25-bfcb-40c7-97d1-667705ad2223/ima= ges/0a7013db-68fd-4c42-bc2e-cc8d7a05ca18/f184ecd1-0001-4739-af71-250b41= 2345d6', 'chain': [{'path': '/rhev/data-center/332694bb-364a-434e-b23f-= 5fef985d3cbd/26187d25-bfcb-40c7-97d1-667705ad2223/images/0a7013db-68fd-= 4c42-bc2e-cc8d7a05ca18/f184ecd1-0001-4739-af71-250b412345d6', 'domainID= ': '26187d25-bfcb-40c7-97d1-667705ad2223', 'volumeID': 'f184ecd1-0001-4= 739-af71-250b412345d6', 'imageID': '0a7013db-68fd-4c42-bc2e-cc8d7a05ca1= 8'}]} Thread-7808::DEBUG::2012-09-20 06:= 47:02,024::task::588::TaskManager.Task::(_updateState) Task=3D`83579cfe= -4384-4b76-8bb0-979ed2b60739`::moving from state preparing -> state = finished Thread-7808::DEBUG::2012-09-20 06:= 47:02,025::resourceManager::809::ResourceManager.Owner::(releaseAll) Ow= ner.releaseAll requests {} resources {'Storage.26187d25-bfcb-40c7-97d1-= 667705ad2223': < ResourceRef 'Storage.26187d25-bfcb-40c7-97d1-667705= ad2223', isValid: 'True' obj: 'None'>} Thread-7808::DEBUG::2012-09-20 06:= 47:02,025::resourceManager::844::ResourceManager.Owner::(cancelAll) Own= er.cancelAll requests {} Thread-7808::DEBUG::2012-09-20 06:= 47:02,025::resourceManager::538::ResourceManager::(releaseResource) Try= ing to release resource 'Storage.26187d25-bfcb-40c7-97d1-667705ad2223'<= /font> Thread-7808::DEBUG::2012-09-20 06:= 47:02,025::resourceManager::553::ResourceManager::(releaseResource) Rel= eased resource 'Storage.26187d25-bfcb-40c7-97d1-667705ad2223' (0 active= users) Thread-7808::DEBUG::2012-09-20 06:= 47:02,026::resourceManager::558::ResourceManager::(releaseResource) Res= ource 'Storage.26187d25-bfcb-40c7-97d1-667705ad2223' is free, finding o= ut if anyone is waiting for it. Thread-7808::DEBUG::2012-09-20 06:= 47:02,026::resourceManager::565::ResourceManager::(releaseResource) No = one is waiting for resource 'Storage.26187d25-bfcb-40c7-97d1-667705ad22= 23', Clearing records. Thread-7808::DEBUG::2012-09-20 06:= 47:02,026::task::978::TaskManager.Task::(_decref) Task=3D`83579cfe-4384= -4b76-8bb0-979ed2b60739`::ref 0 aborting False Thread-7808::INFO::2012-09-20 06:4= 7:02,026::clientIF::274::vds::(prepareVolumePath) prepared volume path:= /rhev/data-center/332694bb-364a-434e-b23f-5fef985d3cbd/26187d25-bfcb-4= 0c7-97d1-667705ad2223/images/0a7013db-68fd-4c42-bc2e-cc8d7a05ca18/f184e= cd1-0001-4739-af71-250b412345d6 Thread-7808::DEBUG::2012-09-20 06:= 47:02,037::libvirtvm::1338::vm.Vm::(_run) vmId=3D`509e608c-e657-473a-b0= 31-f0811da96bde`::<?xml version=3D"1.0" encoding=3D"u= tf-8"?> <domain type=3D"kvm"&= gt; <name>CentOS6Thames&= lt;/name> <uuid>509e608c-e657-= 473a-b031-f0811da96bde</uuid> <memory>1048576</= memory> <currentMemory>10485= 76</currentMemory> <vcpu>1</vcpu>= <devices> = <channel type=3D= "unix"> <target= name=3D"com.redhat.rhevm.vdsm" type=3D"virtio"/&gt= ; <source= mode=3D"bind" path=3D"/var/lib/libvirt/qemu/channels/Ce= ntOS6Thames.com.redhat.rhevm.vdsm"/> </channel></= font> <input bus=3D&q= uot;ps2" type=3D"mouse"/> <channel type=3D= "spicevmc"> <target= name=3D"com.redhat.spice.0" type=3D"virtio"/></= font> </channel></= font> <graphics autop= ort=3D"yes" keymap=3D"en-us" passwd=3D"*****&q= uot; passwdValidTo=3D"1970-01-01T00:00:01" port=3D"-1&qu= ot; tlsPort=3D"-1" type=3D"spice"> <channe= l mode=3D"secure" name=3D"main"/> <channe= l mode=3D"secure" name=3D"inputs"/> <channe= l mode=3D"secure" name=3D"cursor"/> <channe= l mode=3D&quo t;secure" name=3D"playback"/> <channe= l mode=3D"secure" name=3D"record"/> <channe= l mode=3D"secure" name=3D"display"/> <listen= network=3D"vdsm-ovirtmgmt" type=3D"network"/></= font> </graphics><= /font> <console type=3D= "pty"> <target= port=3D"0" type=3D"virtio"/> </console></= font> <controller typ= e=3D"usb"> <addres= s domain=3D"0x0000" function=3D"0x2" slot=3D&quo= t;0x01" type=3D"pci" bus=3D"0x00"/>= </controller&gt= ; <video></fon= t> <addres= s domain=3D"0x0000" function=3D"0x0" slot=3D&quo= t;0x02" type=3D"pci" bus=3D"0x00"/>= <model = heads=3D"1" type=3D"qxl" vram=3D"65536"/&= gt; </video></fo= nt> <interface type= =3D"bridge"> <addres= s domain=3D"0x0000" function=3D"0x0" slot=3D&quo= t;0x03" type=3D"pci" bus=3D"0x00"/>= <mac ad= dress=3D"00:1a:4a:a8:0a:00"/> <model = type=3D"virtio"/> <source= bridge=3D"ovirtmgmt"/> </interface>= <memballoon mod= el=3D"virtio"/> <disk device=3D= "cdrom" snapshot=3D"no" type=3D"file">= <addres= s bus=3D"1" controller=3D"0" target=3D"0&qu= ot; type=3D"drive" unit=3D"0"/> <source= file=3D"" startupPolicy=3D"optional"/><b= r> <target= bus=3D"ide" dev=3D"hdc"/> <readon= ly/> <serial= ></serial> </disk></fon= t> <disk device=3D= "disk" snapshot=3D"no" type=3D"block">= <addres= s domain=3D"0x0000" function=3D"0x0" slot=3D&quo= t;0x05" type=3D"pci" bus=3D"0x00"/>= <source= dev=3D"/rhev/data-center/332694bb-364a-434e-b23f-5fef985d3cbd/261= 87d25-bfcb-40c7-97d1-667705ad2223/images/0a7013db-68fd-4c42-bc2e-cc8d7a= 05ca18/f184ecd1-0001-4739-af71-250b412345d6"/> <target= bus=3D"virtio" dev=3D"vda"/> <serial= >0a7013db-68fd-4c42-bc2e-cc8d7a05ca18</serial> <driver= cache=3D"none" error_policy=3D"stop" io=3D"na= tive" name=3D"qemu" type=3D"qcow2"/>= </disk></fon= t> </devices><br= > <os> <type arch=3D&q= uot;x86_64" machine=3D"pc-0.14">hvm</type></fon= t> <smbios mode=3D= "sysinfo"/> </os> <sysinfo type=3D"s= mbios"> <system></fo= nt> <entry = name=3D"manufacturer">Red Hat</entry> <entry = name=3D"product">RHEV Hypervisor</entry> <entry = name=3D"version">17-1</entry> <entry = name=3D"serial">31323334-3535-4C44-3643-4D5633393936_00:19= :bb:39:97:4a</entry> <entry = name=3D"uuid">509e608c-e657-473a-b031-f0811da96bde</ent= ry> </system></f= ont> </sysinfo><br= > <clock adjustment=3D&qu= ot;-1" offset=3D"variable"> <timer name=3D&= quot;rtc" tickpolicy=3D"catchup"/> </clock> <features><br= > <acpi/></fon= t> </features><b= r> <cpu match=3D"exac= t"> <model>Conro= e</model> <topology cores= =3D"1" sockets=3D"1" threads=3D"1"/></= font> </cpu> </domain> Thread-7808::DEBUG::2012-09-20 06:= 47:02,426::vm::580::vm.Vm::(_startUnderlyingVm) vmId=3D`509e608c-e657-4= 73a-b031-f0811da96bde`::_ongoingCreations released Thread-7808::ERROR::2012-09-20 06:= 47:02,427::vm::604::vm.Vm::(_startUnderlyingVm) vmId=3D`509e608c-e657-4= 73a-b031-f0811da96bde`::The vm start process failed Traceback (most recent call last):= File "/usr/share/vdsm/vm.py= ", line 570, in _startUnderlyingVm File "/usr/share/vdsm/libvi= rtvm.py", line 1364, in _run File "/usr/lib/python2.7/si= te-packages/vdsm/libvirtconnection.py", line 82, in wrapper= File "/usr/lib64/python2.7/= site-packages/libvirt.py", line 2420, in createXML libvirtError: unsupported configur= ation: spice secure channels set in XML configuration, but TLS is disab= led in qemu.conf Thread-7808::DEBUG::2012-09-20 06:= 47:02,430::vm::920::vm.Vm::(setDownStatus) vmId=3D`509e608c-e657-473a-b= 031-f0811da96bde`::Changed state to Down: unsupported configuration: sp= ice secure channels set in XML configuration, but TLS is disabled in qe= mu.conf Dummy-1960::DEBUG::2012-09-20 06:4= 7:03,145::__init__::1249::Storage.Misc.excCmd::(_log) 'dd if=3D/rhev/da= ta-center/332694bb-364a-434e-b23f-5fef985d3cbd/mastersd/dom_md/inbox if= lag=3Ddirect,fullblock count=3D1 bs=3D1024000' (cwd None) Dummy-1960::DEBUG::2012-09-20 06:4= 7:03,230::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err&= gt; =3D '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied= , 0.0496138 s, 20.6 MB/s\n'; <rc> =3D 0 Thread-7810::DEBUG::2012-09-20 06:= 47:03,560::BindingXMLRPC::156::vds::(wrapper) [192.168.10.10]<br= > Thread-7810::DEBUG::2012-09-20 06:= 47:03,561::task::588::TaskManager.Task::(_updateState) Task=3D`9bc08c7e= -010f-45c2-940a-3fd8361785d5`::moving from state init -> state prepa= ring Thread-7810::INFO::2012-09-20 06:4= 7:03,561::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmSt= atus(spUUID=3D'332694bb-364a-434e-b23f-5fef985d3cbd', options=3DNone)</= font> Thread-7810::INFO::2012-09-20 06:4= 7:03,562::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmSt= atus, Return response: {'spm_st': {'spmId': 3, 'spmStatus': 'SPM', 'spm= Lver': 0}} Thread-7810::DEBUG::2012-09-20 06:= 47:03,562::task::1172::TaskManager.Task::(prepare) Task=3D`9bc08c7e-010= f-45c2-940a-3fd8361785d5`::finished: {'spm_st': {'spmId': 3, 'spmStatus= ': 'SPM', 'spmLver': 0}} Thread-7810::DEBUG::2012-09-20 06:= 47:03,562::task::588::TaskManager.Task::(_updateState) Task=3D`9bc08c7e= -010f-45c2-940a-3fd8361785d5`::moving from state preparing -> state = finished Thread-7810::DEBUG::2012-09-20 06:= 47:03,562::resourceManager::809::ResourceManager.Owner::(releaseAll) Ow= ner.releaseAll requests {} resources {} Thread-7810::DEBUG::2012-09-20 06:= 47:03,562::resourceManager::844::ResourceManager.Owner::(cancelAll) Own= er.cancelAll requests {} Thread-7810::DEBUG::2012-09-20 06:= 47:03,563::task::978::TaskManager.Task::(_decref) Task=3D`9bc08c7e-010f= -45c2-940a-3fd8361785d5`::ref 0 aborting False Thread-7812::DEBUG::2012-09-20 06:= 47:03,595::BindingXMLRPC::156::vds::(wrapper) [192.168.10.10]<br= > Thread-7812::DEBUG::2012-09-20 06:= 47:03,595::task::588::TaskManager.Task::(_updateState) Task=3D`8e330204= -753f-422d-b286-a360410806be`::moving from state init -> state prepa= ring Thread-7812::INFO::2012-09-20 06:4= 7:03,596::logUtils::37::dispatcher::(wrapper) Run and protect: getStora= gePoolInfo(spUUID=3D'332694bb-364a-434e-b23f-5fef985d3cbd', options=3DN= one) Thread-7812::DEBUG::2012-09-20 06:= 47:03,596::resourceManager::175::ResourceManager.Request::(__init__) Re= sName=3D`Storage.332694bb-364a-434e-b23f-5fef985d3cbd`ReqID=3D`a7222834= -3565-4e28-a15f-72692ef664c6`::Request was made in '/usr/share/vdsm/sto= rage/resourceManager.py' line '485' at 'registerResource' Thread-7812::DEBUG::2012-09-20 06:= 47:03,596::resourceManager::486::ResourceManager::(registerResource) Tr= ying to register resource 'Storage.332694bb-364a-434e-b23f-5fef985d3cbd= ' for lock type 'shared' Thread-7812::DEBUG::2012-09-20 06:= 47:03,597::resourceManager::528::ResourceManager::(registerResource) Re= source 'Storage.332694bb-364a-434e-b23f-5fef985d3cbd' is free. Now lock= ing as 'shared' (1 active user) Thread-7812::DEBUG::2012-09-20 06:= 47:03,597::resourceManager::212::ResourceManager.Request::(grant) ResNa= me=3D`Storage.332694bb-364a-434e-b23f-5fef985d3cbd`ReqID=3D`a7222834-35= 65-4e28-a15f-72692ef664c6`::Granted request Thread-7812::DEBUG::2012-09-20 06:= 47:03,597::task::817::TaskManager.Task::(resourceAcquired) Task=3D`8e33= 0204-753f-422d-b286-a360410806be`::_resourcesAcquired: Storage.332694bb= -364a-434e-b23f-5fef985d3cbd (shared) Thread-7812::DEBUG::2012-09-20 06:= 47:03,598::task::978::TaskManager.Task::(_decref) Task=3D`8e330204-753f= -422d-b286-a360410806be`::ref 1 aborting False Thread-7813::DEBUG::2012-09-20 06:= 47:03,598::BindingXMLRPC::859::vds::(wrapper) client [192.168.10.10]::c= all vmGetStats with ('509e608c-e657-473a-b031-f0811da96bde',) {}= Thread-7812::INFO::2012-09-20 06:4= 7:03,599::logUtils::39::dispatcher::(wrapper) Run and protect: getStora= gePoolInfo, Return response: {'info': {'spm_id': 3, 'master_uuid': '261= 87d25-bfcb-40c7-97d1-667705ad2223', 'name': 'Valeka', 'version': '2', '= domains': u'26187d25-bfcb-40c7-97d1-667705ad2223:Active,90104c3d-837b-4= 7dd-8c82-dda92eec30d9:Active', 'pool_status': 'connected', 'isoprefix':= u'/rhev/data-center/332694bb-364a-434e-b23f-5fef985d3cbd/90104c3d-837b= -47dd-8c82-dda92eec30d9/images/11111111-1111-1111-1111-111111111111', '= type': 'ISCSI', 'master_ver': 1, 'lver': 0}, 'dominfo': {u'26187d25-bfc= b-40c7-97d1-667705ad2223': {'status': u'Active', 'diskfree': '167409772= 1344', 'alerts': [], 'disktotal': '1799591297024'}, u'90104c3d-837b-47d= d-8c82-dda92eec30d9': {'status': u'Active', 'diskfree': '423518535680',= 'alerts': [], 'disktotal': '492264226816'}}} Thread-7813::DEBUG::2012-09-20 06:= 47:03,600::BindingXMLRPC::865::vds::(wrapper) return vmGetStats with {'= status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Down= ', 'hash': '0', 'exitMessage': 'unsupported configuration: spice secure= channels set in XML configuration, but TLS is disabled in qemu.conf', = 'vmId': '509e608c-e657-473a-b031-f0811da96bde', 'timeOffset': '-1', 'ex= itCode': 1}]} Thread-7812::DEBUG::2012-09-20 06:= 47:03,600::task::1172::TaskManager.Task::(prepare) Task=3D`8e330204-753= f-422d-b286-a360410806be`::finished: {'info': {'spm_id': 3, 'master_uui= d': '26187d25-bfcb-40c7-97d1-667705ad2223', 'name': 'Valeka', 'version'= : '2', 'domains': u'26187d25-bfcb-40c7-97d1-667705ad2223:Active,90104c3= d-837b-47dd-8c82-dda92eec30d9:Active', 'pool_status': 'connected', 'iso= prefix': u'/rhev/data-center/332694bb-364a-434e-b23f-5fef985d3cbd/90104= c3d-837b-47dd-8c82-dda92eec30d9/images/11111111-1111-1111-1111-11111111= 1111', 'type': 'ISCSI', 'master_ver': 1, 'lver': 0}, 'dominfo': {u'2618= 7d25-bfcb-40c7-97d1-667705ad2223': {'status': u'Active', 'diskfree': '1= 674097721344', 'alerts': [], 'disktotal': '1799591297024'}, u'90104c3d-= 837b-47dd-8c82-dda92eec30d9': {'status': u'Active', 'diskfree': '423518= 535680', 'alerts': [], 'disktotal': '492264226816'}}} Thread-7812::DEBUG::2012-09-20 06:= 47:03,601::task::588::TaskManager.Task::(_updateState) Task=3D`8e330204= -753f-422d-b286-a360410806be`::moving from state preparing -> state = finished Thread-7812::DEBUG::2012-09-20 06:= 47:03,601::resourceManager::809::ResourceManager.Owner::(releaseAll) Ow= ner.releaseAll requests {} resources {'Storage.332694bb-364a-434e-b23f-= 5fef985d3cbd': < ResourceRef 'Storage.332694bb-364a-434e-b23f-5fef98= 5d3cbd', isValid: 'True' obj: 'None'>} Thread-7812::DEBUG::2012-09-20 06:= 47:03,601::resourceManager::844::ResourceManager.Owner::(cancelAll) Own= er.cancelAll requests {} Thread-7812::DEBUG::2012-09-20 06:= 47:03,602::resourceManager::538::ResourceManager::(releaseResource) Try= ing to release resource 'Storage.332694bb-364a-434e-b23f-5fef985d3cbd'<= /font> Thread-7812::DEBUG::2012-09-20 06:= 47:03,602::resourceManager::553::ResourceManager::(releaseResource) Rel= eased resource 'Storage.332694bb-364a-434e-b23f-5fef985d3cbd' (0 active= users) Thread-7812::DEBUG::2012-09-20 06:= 47:03,602::resourceManager::558::ResourceManager::(releaseResource) Res= ource 'Storage.332694bb-364a-434e-b23f-5fef985d3cbd' is free, finding o= ut if anyone is waiting for it. Thread-7812::DEBUG::2012-09-20 06:= 47:03,602::resourceManager::565::ResourceManager::(releaseResource) No = one is waiting for resource 'Storage.332694bb-364a-434e-b23f-5fef985d3c= bd', Clearing records. Thread-7812::DEBUG::2012-09-20 06:= 47:03,602::task::978::TaskManager.Task::(_decref) Task=3D`8e330204-753f= -422d-b286-a360410806be`::ref 0 aborting False Thread-7814::DEBUG::2012-09-20 06:= 47:03,658::BindingXMLRPC::859::vds::(wrapper) client [192.168.10.10]::c= all vmDestroy with ('509e608c-e657-473a-b031-f0811da96bde',) {}<= br> Thread-7814::INFO::2012-09-20 06:4= 7:03,658::API::317::vds::(destroy) vmContainerLock acquired by vm 509e6= 08c-e657-473a-b031-f0811da96bde Thread-7814::DEBUG::2012-09-20 06:= 47:03,658::libvirtvm::2085::vm.Vm::(destroy) vmId=3D`509e608c-e657-473a= -b031-f0811da96bde`::destroy Called Thread-7814::INFO::2012-09-20 06:4= 7:03,658::libvirtvm::2040::vm.Vm::(releaseVm) vmId=3D`509e608c-e657-473= a-b031-f0811da96bde`::Release VM resources Thread-7814::WARNING::2012-09-20 0= 6:47:03,659::vm::328::vm.Vm::(_set_lastStatus) vmId=3D`509e608c-e657-47= 3a-b031-f0811da96bde`::trying to set state to Powering down when alread= y Down Thread-7814::DEBUG::2012-09-20 06:= 47:03,659::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -= n /usr/sbin/service ksmtuned retune' (cwd None) Thread-7814::DEBUG::2012-09-20 06:= 47:03,696::__init__::1249::Storage.Misc.excCmd::(_log) FAILED: <err&= gt; =3D 'Redirecting to /bin/systemctl retune ksmtuned.service\nUnknow= n operation retune\n'; <rc> =3D 1 Thread-7814::DEBUG::2012-09-20 06:= 47:03,697::task::588::TaskManager.Task::(_updateState) Task=3D`e97820bb= -547d-4e7a-9249-ece94285bac8`::moving from state init -> state prepa= ring Thread-7814::INFO::2012-09-20 06:4= 7:03,698::logUtils::37::dispatcher::(wrapper) Run and protect: inapprop= riateDevices(thiefId=3D'509e608c-e657-473a-b031-f0811da96bde')<b= r> Thread-7814::INFO::2012-09-20 06:4= 7:03,699::logUtils::39::dispatcher::(wrapper) Run and protect: inapprop= riateDevices, Return response: None Thread-7814::DEBUG::2012-09-20 06:= 47:03,699::task::1172::TaskManager.Task::(prepare) Task=3D`e97820bb-547= d-4e7a-9249-ece94285bac8`::finished: None Thread-7814::DEBUG::2012-09-20 06:= 47:03,700::task::588::TaskManager.Task::(_updateState) Task=3D`e97820bb= -547d-4e7a-9249-ece94285bac8`::moving from state preparing -> state = finished Thread-7814::DEBUG::2012-09-20 06:= 47:03,700::resourceManager::809::ResourceManager.Owner::(releaseAll) Ow= ner.releaseAll requests {} resources {} Thread-7814::DEBUG::2012-09-20 06:= 47:03,700::resourceManager::844::ResourceManager.Owner::(cancelAll) Own= er.cancelAll requests {} Thread-7814::DEBUG::2012-09-20 06:= 47:03,700::task::978::TaskManager.Task::(_decref) Task=3D`e97820bb-547d= -4e7a-9249-ece94285bac8`::ref 0 aborting False Thread-7814::DEBUG::2012-09-20 06:= 47:03,700::libvirtvm::2080::vm.Vm::(deleteVm) vmId=3D`509e608c-e657-473= a-b031-f0811da96bde`::Total desktops after destroy of 509e608c-e657-473= a-b031-f0811da96bde is 0 Thread-7814::DEBUG::2012-09-20 06:= 47:03,701::BindingXMLRPC::865::vds::(wrapper) return vmDestroy with {'s= tatus': {'message': 'Machine destroyed', 'code': 0}} Thread-481::DEBUG::2012-09-20 06:4= 7:04,302::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/dd ifla= g=3Ddirect if=3D/dev/26187d25-bfcb-40c7-97d1-667705ad2223/metadata bs=3D= 4096 count=3D1' (cwd None) Thread-481::DEBUG::2012-09-20 06:4= 7:04,317::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err&= gt; =3D '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0= .000843551 s, 4.9 MB/s\n'; <rc> =3D 0 Dummy-1960::DEBUG::2012-09-20 06:4= 7:05,239::__init__::1249::Storage.Misc.excCmd::(_log) 'dd if=3D/rhev/da= ta-center/332694bb-364a-434e-b23f-5fef985d3cbd/mastersd/dom_md/inbox if= lag=3Ddirect,fullblock count=3D1 bs=3D1024000' (cwd None) Dummy-1960::DEBUG::2012-09-20 06:4= 7:05,323::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err&= gt; =3D '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied= , 0.0476578 s, 21.5 MB/s\n'; <rc> =3D 0 Thread-7815::DEBUG::2012-09-20 06:= 47:05,819::task::588::TaskManager.Task::(_updateState) Task=3D`ef5f39d0= -241c-44b5-a771-da364468b498`::moving from state init -> state prepa= ring Thread-7815::INFO::2012-09-20 06:4= 7:05,819::logUtils::37::dispatcher::(wrapper) Run and protect: repoStat= s(options=3DNone) Thread-7815::INFO::2012-09-20 06:4= 7:05,820::logUtils::39::dispatcher::(wrapper) Run and protect: repoStat= s, Return response: {'26187d25-bfcb-40c7-97d1-667705ad2223': {'delay': = '0.0156102180481', 'lastCheck': 1348123624.512314, 'code': 0, 'valid': = True}, '90104c3d-837b-47dd-8c82-dda92eec30d9': {'delay': '0.00118303298= 95', 'lastCheck': 1348123617.41074, 'code': 0, 'valid': True}}<b= r> Thread-7815::DEBUG::2012-09-20 06:= 47:05,820::task::1172::TaskManager.Task::(prepare) Task=3D`ef5f39d0-241= c-44b5-a771-da364468b498`::finished: {'26187d25-bfcb-40c7-97d1-667705ad= 2223': {'delay': '0.0156102180481', 'lastCheck': 1348123624.512314, 'co= de': 0, 'valid': True}, '90104c3d-837b-47dd-8c82-dda92eec30d9': {'delay= ': '0.0011830329895', 'lastCheck': 1348123617.41074, 'code': 0, 'valid'= : True}} Thread-7815::DEBUG::2012-09-20 06:= 47:05,820::task::588::TaskManager.Task::(_updateState) Task=3D`ef5f39d0= -241c-44b5-a771-da364468b498`::moving from state preparing -> state = finished Thread-7815::DEBUG::2012-09-20 06:= 47:05,820::resourceManager::809::ResourceManager.Owner::(releaseAll) Ow= ner.releaseAll requests {} resources {} Thread-7815::DEBUG::2012-09-20 06:= 47:05,821::resourceManager::844::ResourceManager.Owner::(cancelAll) Own= er.cancelAll requests {} Thread-7815::DEBUG::2012-09-20 06:= 47:05,821::task::978::TaskManager.Task::(_decref) Task=3D`ef5f39d0-241c= -44b5-a771-da364468b498`::ref 0 aborting False Dummy-1960::DEBUG::2012-09-20 06:4= 7:07,332::__init__::1249::Storage.Misc.excCmd::(_log) 'dd if=3D/rhev/da= ta-center/332694bb-364a-434e-b23f-5fef985d3cbd/mastersd/dom_md/inbox if= lag=3Ddirect,fullblock count=3D1 bs=3D1024000' (cwd None) Dummy-1960::DEBUG::2012-09-20 06:4= 7:07,458::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err&= gt; =3D '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied= , 0.0478973 s, 21.4 MB/s\n'; <rc> =3D 0 Dummy-1960::DEBUG::2012-09-20 06:4= 7:09,502::__init__::1249::Storage.Misc.excCmd::(_log) 'dd if=3D/rhev/da= ta-center/332694bb-364a-434e-b23f-5fef985d3cbd/mastersd/dom_md/inbox if= lag=3Ddirect,fullblock count=3D1 bs=3D1024000' (cwd None) Dummy-1960::DEBUG::2012-09-20 06:4= 7:09,586::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err&= gt; =3D '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied= , 0.0485543 s, 21.1 MB/s\n'; <rc> =3D 0 If I try to create new server I ha= ve the same error message. - - Dmitriy Pyryakov <ul style=3D"padding-left: 0pt">Vi= mpelCom Ltd.</ul> </body></html>= --0__=C9BBF0ECDFB7B2218f9e8a93df938690918cC9BBF0ECDFB7B221--

2 2

[Users] oVirt Weekly Meeting Minutes -- 2012-09-19
by Mike Burns 19 Sep '12

19 Sep '12

Minutes: http://ovirt.org/meetings/ovirt/2012/ovirt.2012-09-19-14.00.html Minutes (text): http://ovirt.org/meetings/ovirt/2012/ovirt.2012-09-19-14.00.txt Log: http://ovirt.org/meetings/ovirt/2012/ovirt.2012-09-19-14.00.log.html ========================= #ovirt: oVirt Weekly Sync ========================= Meeting started by mburns at 14:00:14 UTC. The full logs are available at http://ovirt.org/meetings/ovirt/2012/ovirt.2012-09-19-14.00.log.html . Meeting summary --------------- * agenda and roll call (mburns, 14:00:22) * Project Manager Election results (mburns, 14:02:47) * as we were organizing, we decided against the election (mburns, 14:03:25) * it was agreed that mburns would serve as Project Manager (mburns, 14:03:38) * and mgoldboi would serve as backup (mburns, 14:03:49) * we'll probably split the role a bit with mgoldboi taking the lead on some parts and mburns on others (mburns, 14:04:35) * Release Status (mburns, 14:05:10) * Devel freeze currently scheduled for Nov 14 (mburns, 14:05:41) * GA currently scheduled for mid Dec (mburns, 14:06:03) * as of right now, the plan is to make the release primarily a bug fix and stabilization release (mburns, 14:06:35) * mburns will be working on pulling together feature lists from the component maintainers over the next couple weeks (mburns, 14:07:12) * subproject status -- Node (mburns, 14:08:56) * still no movement on the nfs issue, though it appears to be something to be handled by the vdsm team (mburns, 14:09:20) * mburns working on a centos based node (though not overly close at the moment) (mburns, 14:09:48) * team is currently in more of a bug-fix mode than a new feature mode, but will have planned features list for 3.2 soon (mburns, 14:11:07) * subproject status -- vdsm (mburns, 14:11:22) * nothing to report (mburns, 14:13:54) * subproject status -- engine (mburns, 14:14:04) * nothing new to report (mburns, 14:14:55) * subproject status -- infra (mburns, 14:15:08) * Infra trying to tie up temporary hosting, Jenkins host turns out to be fairly costly need, so I'm collecting the recommendation to see if I can get more budget approved for a short term (quaid, 14:17:18) * we should be able to switch Gerrit over to a better solution under the current approved budget spend (quaid, 14:17:45) * Jenkins needs fast IO & RAID 5 or 10 is expensive under hosting solutions (quaid, 14:19:41) * I talked with RHT IT about hosting, that is coming down the pipe soon (quaid, 14:19:57) * LINK: http://ovirt.org/meetings/ovirt/2012/ovirt.2012-09-18-14.13.html (quaid, 14:21:19) * workshops (mburns, 14:21:46) * for Bangalore workshop, jbrooks dneary quaid have agreed to help with surveys (mburns, 14:24:32) * Bangalore split into 2 days, one dev focused, one user focused (mburns, 14:24:47) * for KVM Forum + oVirt Workshop, jbrooks is working on pre-attendee survey (mburns, 14:25:24) * looking for board companies to help spread the word (mburns, 14:25:36) * lh is stepping into more of a consultant role and attendee outreach (mburns, 14:26:28) * ACTION: Board companies help spread the word about KVM Forum + oVirt (quaid, 14:26:29) * Bangalore is currently full (mburns, 14:26:46) * KVM Forum+oVirt is at 25% currently (50 out of 200) (mburns, 14:27:40) * we need CFP submissions for oVirt Workshop at KVM Forum/LinuxCon Europe (mburns, 14:27:56) * workshop at NetApp in planning for January (mburns, 14:29:45) * Other Topics (mburns, 14:30:27) * mburns is out for next weeks meeting, mgoldboi will run the meeting instead (mburns, 14:30:49) * Website (mburns, 14:31:10) * LINK: http://mediawiki-garrett.rhcloud.com/ (garrett_, 14:31:59) * LINK: http://mediawiki-garrett.rhcloud.com/ (mburns, 14:32:14) * demo version of ovirt.org completely in mediawiki (mburns, 14:45:22) * some debate about location of search box (mburns, 14:45:30) * works completely with existing wiki content (mburns, 14:45:50) * LINK: http://mediawiki-garrett.rhcloud.com/OVirt_3.1_release_notes ← here are the release notes, for example (garrett_, 14:46:30) * plan for deploying this to production is included on the mailing lists (mburns, 14:52:48) * please give feedback on site design and plan forward on list (mburns, 14:53:10) * LINK: http://lists.ovirt.org/pipermail/infra/2012-September/001112.html (mburns, 14:54:10) * LINK: http://lists.ovirt.org/pipermail/arch/2012-September/000908.html (dneary, 14:54:42) * ACTION: quaid to talk with OpenShift folks about the 'ovirt' namespace and account (quaid, 14:59:26) Meeting ended at 15:03:03 UTC. Action Items ------------ * Board companies help spread the word about KVM Forum + oVirt * quaid to talk with OpenShift folks about the 'ovirt' namespace and account Action Items, by person ----------------------- * quaid * quaid to talk with OpenShift folks about the 'ovirt' namespace and account * **UNASSIGNED** * Board companies help spread the word about KVM Forum + oVirt People Present (lines said) --------------------------- * garrett_ (115) * mburns (89) * quaid (35) * lh (27) * sgordon_ (22) * dneary (18) * ovirtbot (14) * jb_netapp (4) * Guest7524 (2) * fsimonce (2) * doron (1) * RobertM (1) * dustins (1) * mgoldboi (0) Generated by `MeetBot`_ 0.1.4 .. _`MeetBot`: http://wiki.debian.org/MeetBot

2 1

[Users] Using vioserial in Win7/2008R2 stalls the guest
by Karli Sjöberg 19 Sep '12

19 Sep '12

--_000_687C49F8D246408587877C310DEFB7B0sluse_ Content-Type: text/plain; charset="iso-8859-1" Content-Transfer-Encoding: quoted-printable Hey all, I have noticed that using the virtio serial driver in Windows 7 and 2008R2 = guests stalls the guests with 100% load on guest CPU. This happens both on = guests that have been active for a while without the driver, and then you t= ry loading it, or with installing new guests and loading this particular dr= iver in the windows installer. I have downloaded the virtio-win-0.1.30.iso = from linux-kvm ftp. Has anyone else noticed this in oVirt-3.1? I haven=B4t = been able to test this outside of oVirt, directly with KVM, so I don=B4t kn= ow if it=B4s an oVirt or KVM specific issue, I=B4m just letting everyone kn= ow this has happened, and if ovirt-engine is supposed to use this serial in= terface to "talk" with the guest back and forth; that=B4s going to hard to = do if it=B4s stalled:) Med V=E4nliga H=E4lsningar ---------------------------------------------------------------------------= ---- Karli Sj=F6berg Swedish University of Agricultural Sciences Box 7079 (Visiting Address Kron=E5sv=E4gen 8) S-750 07 Uppsala, Sweden Phone: +46-(0)18-67 15 66 karli.sjoberg(a)slu.se<mailto:karli.sjoberg@adm.slu.se> --_000_687C49F8D246408587877C310DEFB7B0sluse_ Content-Type: text/html; charset="iso-8859-1" Content-ID: <2BE03B5B8A02CE45AD47209BF97BB151(a)ad.slu.se> Content-Transfer-Encoding: quoted-printable <html> <head> <meta http-equiv=3D"Content-Type" content=3D"text/html; charset=3Diso-8859-= 1"> </head> <body style=3D"word-wrap: break-word; -webkit-nbsp-mode: space; -webkit-lin= e-break: after-white-space; "> Hey all, <div> </div> <div>I have noticed that using the virtio serial driver in Windows 7 and 20= 08R2 guests stalls the guests with 100% load on guest CPU. This happens bot= h on guests that have been active for a while without the driver, and then = you try loading it, or with installing new guests and loading this particular driver in the windows installer. I = have downloaded the virtio-win-0.1.30.iso from linux-kvm ftp. Has anyone el= se noticed this in oVirt-3.1? I haven=B4t been able to test this outside of= oVirt, directly with KVM, so I don=B4t know if it=B4s an oVirt or KVM specific issue, I=B4m just letting everyone= know this has happened, and if ovirt-engine is supposed to use this serial= interface to "talk" with the guest back and forth; that=B4s goin= g to hard to do if it=B4s stalled:)  <div><span class=3D"Apple-style-span" style=3D"border-collapse: separate; c= olor: rgb(0, 0, 0); font-family: Helvetica; font-style: normal; font-varian= t: normal; font-weight: normal; letter-spacing: normal; line-height: normal= ; orphans: 2; text-align: -webkit-auto; text-indent: 0px; text-transform: n= one; white-space: normal; widows: 2; word-spacing: 0px; -webkit-border-hori= zontal-spacing: 0px; -webkit-border-vertical-spacing: 0px; -webkit-text-dec= orations-in-effect: none; -webkit-text-size-adjust: auto; -webkit-text-stro= ke-width: 0px; font-size: medium; "> <div> </div> <div>Med V=E4nliga H=E4lsningar ---------------------------------------------------------------------------= ---- Karli Sj=F6berg Swedish University of Agricultural Sciences Box 7079 (Visiting Address Kron=E5sv=E4gen 8) S-750 07 Uppsala, Sweden Phone:  +46-(0)18-67 15 66</div> <div><a href=3D"mailto:karli.sjoberg@adm.slu.se">karli.sjoberg(a)slu.se</a></= div> </div> </div> </body> </html> --_000_687C49F8D246408587877C310DEFB7B0sluse_--

2 1

[Users] Features/Vdsm for PPC64
by Andrei Vakhnin 18 Sep '12

18 Sep '12

Looks like ovirt-engine and vdsm support for IBM POWER 7 is on road map. Is there a plan to support IBM POWER6 architecture? We're looking to virtualize 5 x IBM POWER6 BladeCenter H to utilize libvirt and KVM on SLES11 pcc64 blades. Thanks http://wiki.ovirt.org/wiki/Features/Vdsm_for_PPC64 Andrei

2 1

Re: [Users] some problems on ovirt node while testing latest nightly
by Jorick Astrego 17 Sep '12

17 Sep '12

----- Original Message ----- >> - We have Intel Xenon E5520 Nehalem based cpu's in these local storage >> nodes. >> These are still recognized as the Conroe family. Even though >> BZ#737104 was supposed to have been fixed. >> (http://gerrit.ovirt.org/#/c/5035/ ) > Not ovirt-node directly, I don't think, but a couple things to check. > What are the cpu flags on the host (from engine gui)? Is the NX bit > set correctly? This is all cpu info I can find in the engine gui CPU Name: Intel Conroe Family CPU Type: Intel(R) Xeon(R) CPU E5520 @ 2.27GHz This is /proc/cpuinfo processor : 15 vendor_id : GenuineIntel cpu family : 6 model : 26 model name : Intel(R) Xeon(R) CPU E5520 @ 2.27GHz stepping : 5 microcode : 0xf cpu MHz : 1600.000 cache size : 8192 KB physical id : 1 siblings : 8 core id : 3 cpu cores : 4 apicid : 23 initial apicid : 23 fpu : yes fpu_exception : yes cpuid level : 11 wp : yes flags : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx rdtscp lm constant_tsc arch_perfmon pebs bts rep_good nopl xtopology nonstop_tsc aperfmperf pni dtes64 monitor ds_cpl vmx est tm2 ssse3 cx16 xtpr pdcm dca sse4_1 sse4_2 popcnt lahf_lm ida dtherm tpr_shadow vnmi flexpriority ept vpid bogomips : 4532.68 clflush size : 64 cache_alignment : 64 address sizes : 40 bits physical, 48 bits virtual power management: > > - Most of our nodes use iSCSI but some will need local storage. When > trying to setup local storage I get this error: > > > > When I check in the directory there is a directory with a UUID > containing the folder dom_md and images. > > I tried clearing the directory and adding storage domain but I get > permission errors: > > run: "su - vdsm -s /bin/sh" > And then delete the directory with the UUID? How does it get there in the first place? This will make auto deployment a bit more difficult. -- Kind Regards, Jorick Astrego Netbulae B.V.

2 2

[Users] Define vlan (pvid and/or trunk) per vNic ? - openvswitch integration
by Benoit ML 14 Sep '12

14 Sep '12

Hello, I'm writing to the ml to know something about ovirt : Is there any possibilité to define a vlan per vNic (pvid and/or trunk) , for each vnic of VM ? I'm working with openvswitch and i can define this. Well, for us, it's the absolute needed (and killing) feature to define well known n-tiers architecture in a virtual world (web fronted, BDD, load-balancer and so on). I'm interesting by oVirt because it seems to be an integrated web interface. Thank you in advance ! Regards, -- -- Benoit

2 1

[Users] Speakers Needed: Upcoming Workshops
by Leslie Hawthorn 14 Sep '12

14 Sep '12

Hello everyone, First of all, congratulations to the team on today's release of oVirt 3.1! As mentioned in today's weekly status IRC meeting, we would like to ensure we have broad community participation in upcoming workshops. [0] For KVM Forum + oVirt in Barcelona [1], a general call for papers will be issued within the next few days. I will send a note to these lists when details of the CFP have been announced. For the oVirt workshop to be hosted at Red Hat's Bangalore campus on 16 October 2012, it would be wonderful if folks would propose sessions for this workshop. (We have chosen not to go through a formal CFP process for Bangalore so as to leave sufficient time for the KVM Forum + oVirt CFP process to run most smoothly.) If you would like to propose a session for oVirt Bangalore, please email me and I follow up with you. As usual, any questions, please let me know. [0] - http://wiki.ovirt.org/wiki/OVirt_Global_Workshops [1] - http://events.linuxfoundation.org/events/kvm-forum/ Cheers, LH -- Leslie Hawthorn Community Action and Impact Open Source and Standards @ Red Hat identi.ca/lh twitter.com/lhawthorn

5 9

[Users] vdsm/engine do not like Infiniband
by Dead Horse 13 Sep '12

13 Sep '12

When attempting to activate/add a host with Infiniband cards present: vdsm.log Thread-14::DEBUG::2012-09-13 16:16:29,306::BindingXMLRPC::884::vds::(wrapper) return getCapabilities with {'status': {'message': 'Done', 'code': 0}, 'info': {'HBAInventory': {'iSCSI': [{'InitiatorName': 'iqn.2012-09.net.azeroth:kezan'}], 'FC': []}, 'packages2': {'kernel': {'release': '200.29.3.el6uek.x86_64', 'buildtime': 1346177011.0, 'version': '2.6.39'}, 'spice-server': {'release': '10.el6', 'buildtime': 1340343617L, 'version': '0.10.1'}, 'vdsm': {'release': '435.el6', 'buildtime': 1347508928L, 'version': '4.10.0'}, 'qemu-kvm': {'release': '2.295.el6_3.2', 'buildtime': 1346867328L, 'version': '0.12.1.2'}, 'libvirt': {'release': '21.el6_3.4', 'buildtime': 1345740034L, 'version': '0.9.10'}, 'qemu-img': {'release': '2.295.el6_3.2', 'buildtime': 1346867328L, 'version': '0.12.1.2'}}, 'cpuModel': 'Intel(R) Xeon(R) CPU E5540 @ 2.53GHz', 'hooks': {}, 'vmTypes': ['kvm'], 'supportedProtocols': ['2.2', '2.3'], 'networks': {'ovirtmgmt': {'iface': 'ovirtmgmt', 'addr': '3.57.111.31', 'cfg': {'IPV6INIT': 'no', 'IPADDR': '3.57.111.31', 'DELAY': '0', 'PREFIX': '22', 'BOOTPROTO': 'none', 'STP': 'off', 'DEVICE': 'ovirtmgmt', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '255.255.252.0', 'stp': 'off', 'bridged': True, 'gateway': '0.0.0.0', 'ports': ['bond2']}, 'maelstrom': {'iface': 'maelstrom', 'addr': '', 'cfg': {'IPV6INIT': 'no', 'DELAY': '0', 'BOOTPROTO': 'none', 'STP': 'off', 'DEVICE': 'maelstrom', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '', 'stp': 'off', 'bridged': True, 'gateway': '0.0.0.0', 'ports': ['bond0']}, 'twistingnether': {'iface': 'twistingnether', 'addr': '3.70.204.31', 'cfg': {'IPV6INIT': 'no', 'IPADDR': '3.70.204.31', 'DELAY': '0', 'PREFIX': '22', 'BOOTPROTO': 'none', 'STP': 'off', 'DEVICE': 'twistingnether', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '255.255.252.0', 'stp': 'off', 'bridged': True, 'gateway': '3.70.204.254', 'ports': ['bond1']}}, 'bridges': {'ovirtmgmt': {'addr': '3.57.111.31', 'cfg': {'IPV6INIT': 'no', 'IPADDR': '3.57.111.31', 'DELAY': '0', 'PREFIX': '22', 'BOOTPROTO': 'none', 'STP': 'off', 'DEVICE': 'ovirtmgmt', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '255.255.252.0', 'stp': 'off', 'ports': ['bond2']}, 'maelstrom': {'addr': '', 'cfg': {'IPV6INIT': 'no', 'DELAY': '0', 'BOOTPROTO': 'none', 'STP': 'off', 'DEVICE': 'maelstrom', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '', 'stp': 'off', 'ports': ['bond0']}, 'twistingnether': {'addr': '3.70.204.31', 'cfg': {'IPV6INIT': 'no', 'IPADDR': '3.70.204.31', 'DELAY': '0', 'PREFIX': '22', 'BOOTPROTO': 'none', 'STP': 'off', 'DEVICE': 'twistingnether', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '255.255.252.0', 'stp': 'off', 'ports': ['bond1']}}, 'uuid': 'FF200008-FFFF-FFFF-FFFF-00212883CE4C_00:15:17:00:10:0a', 'lastClientIface': 'twistingnether', 'nics': {'ib0': {'addr': '192.168.1.1', 'cfg': {'IPV6INIT': 'no', 'IPADDR': '192.168.1.1', 'MTU': '65520', 'PREFIX': '16', 'BOOTPROTO': 'none', 'CONNECTED_MODE': 'yes', 'DEVICE': 'ib0', 'TYPE': 'Infiniband', 'ONBOOT': 'yes'}, 'mtu': '65520', 'netmask': '255.255.0.0', 'hwaddr': '80:00:04:04:fe:80:00:00:00:00:00:00:00:12:79:ff:ff:b5:b0:f1', 'speed': 0}, 'ib1': {'addr': '', 'cfg': {'IPV6INIT': 'no', 'MTU': '65520', 'BOOTPROTO': 'none', 'CONNECTED_MODE': 'yes', 'DEVICE': 'ib1', 'TYPE': 'Infiniband', 'ONBOOT': 'no'}, 'mtu': '2044', 'netmask': '', 'hwaddr': '80:00:04:05:fe:80:00:00:00:00:00:00:00:12:79:ff:ff:b5:b0:f2', 'speed': 0}, 'eth5': {'permhwaddr': '00:15:17:00:10:0B', 'addr': '', 'cfg': {'SLAVE': 'yes', 'IPV6INIT': 'no', 'HWADDR': '00:15:17:00:10:0B', 'BOOTPROTO': 'none', 'MASTER': 'bond2', 'DEVICE': 'eth5', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '', 'hwaddr': '00:15:17:00:10:0a', 'speed': 1000}, 'eth4': {'permhwaddr': '00:15:17:00:10:0A', 'addr': '', 'cfg': {'SLAVE': 'yes', 'IPV6INIT': 'no', 'HWADDR': '00:15:17:00:10:0A', 'BOOTPROTO': 'none', 'MASTER': 'bond2', 'DEVICE': 'eth4', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '', 'hwaddr': '00:15:17:00:10:0a', 'speed': 1000}, 'eth3': {'permhwaddr': '00:21:28:83:CE:4B', 'addr': '', 'cfg': {'SLAVE': 'yes', 'HWADDR': '00:21:28:83:CE:4B', 'BOOTPROTO': 'none', 'MASTER': 'bond1', 'DEVICE': 'eth3', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '', 'hwaddr': '00:21:28:83:ce:4a', 'speed': 1000}, 'eth2': {'permhwaddr': '00:21:28:83:CE:4A', 'addr': '', 'cfg': {'SLAVE': 'yes', 'HWADDR': '00:21:28:83:CE:4A', 'BOOTPROTO': 'none', 'MASTER': 'bond1', 'DEVICE': 'eth2', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '', 'hwaddr': '00:21:28:83:ce:4a', 'speed': 1000}, 'eth1': {'permhwaddr': '00:21:28:83:CE:49', 'addr': '', 'cfg': {'SLAVE': 'yes', 'IPV6INIT': 'no', 'HWADDR': '00:21:28:83:CE:49', 'BOOTPROTO': 'none', 'MASTER': 'bond0', 'DEVICE': 'eth1', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '', 'hwaddr': '00:21:28:83:ce:48', 'speed': 1000}, 'eth0': {'permhwaddr': '00:21:28:83:CE:48', 'addr': '', 'cfg': {'SLAVE': 'yes', 'IPV6INIT': 'no', 'HWADDR': '00:21:28:83:CE:48', 'BOOTPROTO': 'none', 'MASTER': 'bond0', 'DEVICE': 'eth0', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '', 'hwaddr': '00:21:28:83:ce:48', 'speed': 1000}}, 'software_revision': '435', 'management_ip': '3.57.111.31', 'clusterLevels': ['3.0', '3.1', '3.2'], 'cpuFlags': u'fpu,vme,de,pse,tsc,msr,pae,mce,cx8,apic,sep,mtrr,pge,mca,cmov,pat,pse36,clflush,dts,acpi,mmx,fxsr,sse,sse2,ss,ht,tm,pbe,syscall,nx,rdtscp,lm,constant_tsc,arch_perfmon,pebs,bts,rep_good,nopl,xtopology,nonstop_tsc,aperfmperf,pni,dtes64,monitor,ds_cpl,vmx,est,tm2,ssse3,cx16,xtpr,pdcm,dca,sse4_1,sse4_2,popcnt,lahf_lm,ida,dts,tpr_shadow,vnmi,flexpriority,ept,vpid,model_Nehalem,model_Conroe,model_Penryn', 'ISCSIInitiatorName': 'iqn.2012-09.net.azeroth:kezan', 'netConfigDirty': 'False', 'memSize': '36272', 'reservedMem': '321', 'bondings': {'bond4': {'addr': '', 'cfg': {}, 'mtu': '1500', 'netmask': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00'}, 'bond0': {'addr': '', 'cfg': {'BRIDGE': 'maelstrom', 'IPV6INIT': 'no', 'BOOTPROTO': 'none', 'BONDING_OPTS': 'mode=4 miimon=250 xmit_hash_policy=layer2+3', 'DEVICE': 'bond0', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '', 'slaves': ['eth0', 'eth1'], 'hwaddr': '00:21:28:83:ce:48'}, 'bond1': {'addr': '', 'cfg': {'BRIDGE': 'twistingnether', 'IPV6INIT': 'no', 'BOOTPROTO': 'none', 'BONDING_OPTS': 'mode=4 miimon=250 xmit_hash_policy=layer2+3', 'DEVICE': 'bond1', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '', 'slaves': ['eth2', 'eth3'], 'hwaddr': '00:21:28:83:ce:4a'}, 'bond2': {'addr': '', 'cfg': {'BRIDGE': 'ovirtmgmt', 'IPV6INIT': 'no', 'BOOTPROTO': 'none', 'BONDING_OPTS': 'mode=4 miimon=250 xmit_hash_policy=layer2+3', 'DEVICE': 'bond2', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '', 'slaves': ['eth4', 'eth5'], 'hwaddr': '00:15:17:00:10:0a'}}, 'software_version': '4.10', 'cpuSpeed': '2527.246', 'cpuSockets': '2', 'vlans': {}, 'cpuCores': '8', 'kvmEnabled': 'true', 'guestOverhead': '65', 'supportedRHEVMs': ['3.0', '3.1'], 'version_name': 'Snow Man', 'emulatedMachines': [u'rhel6.3.0', u'pc', u'rhel6.2.0', u'rhel6.1.0', u'rhel6.0.0', u'rhel5.5.0', u'rhel5.4.4', u'rhel5.4.0'], 'operatingSystem': {'release': '1', 'version': '6.3', 'name': 'RHEL'}, 'lastClient': '0.0.0.0'}} engine.log: 2012-09-13 16:16:28,559 INFO [org.ovirt.engine.core.vdsbroker.ActivateVdsVDSCommand] (pool-3-thread-50) [21c70ebd] START, ActivateVdsVDSCommand(vdsId = 1a3d06a8-fde1-11e1-a02d-00151712f280), log id: 4483b716 2012-09-13 16:16:29,339 INFO [org.ovirt.engine.core.vdsbroker.VdsManager] (pool-3-thread-50) [21c70ebd] ResourceManager::activateVds - failed to get VDS = 1a3d06a8-fde1-11e1-a02d-00151712f280 capabilities with error: CallableStatementCallback; SQL [{call insertvds_interface(?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)}]; ERROR: value too long for type character varying(20) Where: SQL statement "INSERT INTO vds_interface(addr, bond_name, bond_type, gateway, id, is_bond, bond_opts, mac_addr, name, network_name, speed, subnet, boot_protocol, type, VDS_ID, vlan_id, mtu, bridged) VALUES(v_addr, v_bond_name, v_bond_type, v_gateway, v_id, v_is_bond, v_bond_opts, v_mac_addr, v_name, v_network_name, v_speed, v_subnet, v_boot_protocol, v_type, v_vds_id, v_vlan_id, v_mtu, v_bridged)" PL/pgSQL function "insertvds_interface" line 3 at SQL statement; nested exception is org.postgresql.util.PSQLException: ERROR: value too long for type character varying(20) Where: SQL statement "INSERT INTO vds_interface(addr, bond_name, bond_type, gateway, id, is_bond, bond_opts, mac_addr, name, network_name, speed, subnet, boot_protocol, type, VDS_ID, vlan_id, mtu, bridged) VALUES(v_addr, v_bond_name, v_bond_type, v_gateway, v_id, v_is_bond, v_bond_opts, v_mac_addr, v_name, v_network_name, v_speed, v_subnet, v_boot_protocol, v_type, v_vds_id, v_vlan_id, v_mtu, v_bridged)" PL/pgSQL function "insertvds_interface" line 3 at SQL statement. 2012-09-13 16:16:29,342 INFO [org.ovirt.engine.core.vdsbroker.VdsManager] (pool-3-thread-50) [21c70ebd] ResourceManager::activateVds - failed to activate VDS = 1a3d06a8-fde1-11e1-a02d-00151712f280 2012-09-13 16:16:29,344 ERROR [org.ovirt.engine.core.vdsbroker.VDSCommandBase] (pool-3-thread-50) [21c70ebd] Command ActivateVdsVDS execution failed. Exception: UncategorizedSQLException: CallableStatementCallback; uncategorized SQLException for SQL [{call updatevdsdynamic(?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)}]; SQL state [25P02]; error code [0]; ERROR: current transaction is aborted, commands ignored until end of transaction block; nested exception is org.postgresql.util.PSQLException: ERROR: current transaction is aborted, commands ignored until end of transaction block 2012-09-13 16:16:29,345 INFO [org.ovirt.engine.core.vdsbroker.ActivateVdsVDSCommand] (pool-3-thread-50) [21c70ebd] FINISH, ActivateVdsVDSCommand, log id: 4483b716 NOTE the length of the Infiniband card "hwaddr" perhaps a clue to the above engine DB insert barf? --> (ERROR: value too long for type character varying(20)) - DHC

2 1