[Users] Host migration problem
Dmitriy A Pyryakov
DPyryakov at ekb.beeline.ru
Thu Sep 20 06:49:24 UTC 2012
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 configuration,
but TLS is disabled in qemu.conf.
engine.log:
[root at 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 =
332694bb-364a-434e-b23f-5fef985d3cbd, ignoreFailoverLimit = false,
compatabilityVersion = 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 =
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= key: 509e608c-e657-473a-b031-f0811da96bde value: VM
, sharedLocks= ]
2012-09-20 12:42:53,415 INFO [org.ovirt.engine.core.bll.RunVmCommand]
(pool-3-thread-50) [a58d974] Running command: RunVmCommand internal: false.
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 =
0a268762-02d7-11e2-b750-0011856cf23e,
vmId=509e608c-e657-473a-b031-f0811da96bde,
vm=org.ovirt.engine.core.common.businessentities.VM at 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 =
0a268762-02d7-11e2-b750-0011856cf23e,
vmId=509e608c-e657-473a-b031-f0811da96bde,
vm=org.ovirt.engine.core.common.businessentities.VM at 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=DEFAULT,memSize=1024,kvmEnable=true,smp=1,emulatedMachine=pc-0.14,vmType=kvm,keyboardLayout=en-us,pitReinjection=false,nice=0,display=qxl,smpCoresPerSocket=1,spiceSecureChannels=smain,sinputs,scursor,splayback,srecord,sdisplay,displayNetwork=ovirtmgmt,timeOffset=-1,transparentHugePages=true,vmId=509e608c
-e657-473a-b031-f0811da96bde,devices=
[Ljava.util.Map;@760db68c,acpiEnable=true,vmName=CentOS6Thames,cpuType=Conroe,custom=
{device_bb912edd-9790-43ff-a758-f1d9f20cb5f5device_f5c86859-5ae9-4a37-9d34-2b9547609622device_20a11f26-6a39-415d-a7bf-95893b9c55b5=VmId=509e608c-e657-473a-b031-f0811da96bde,DeviceId=20a11f26-6a39-415d-a7bf-95893b9c55b5,Device=unix,Type=channel,BootOrder=0,SpecParams=
{},Address={port=1, bus=0, controller=0,
type=virtio-serial},IsManaged=false,IsPlugged=true,IsReadOnly=false,alias=
channel0,
device_bb912edd-9790-43ff-a758-f1d9f20cb5f5=VmId=509e608c-e657-473a-b031-f0811da96bde,DeviceId=bb912edd-9790-43ff-a758-f1d9f20cb5f5,Device=ide,Type=controller,BootOrder=0,SpecParams=
{},Address={bus=0x00, domain=0x0000, type=pci, slot=0x01,
function=0x1},IsManaged=false,IsPlugged=true,IsReadOnly=false,alias=ide0,
device_bb912edd-9790-43ff-a758-f1d9f20cb5f5device_f5c86859-5ae9-4a37-9d34-2b9547609622=VmId=509e608c-e657-473a-b031-f0811da96bde,DeviceId=f5c86859-5ae9-4a37-9d34-2b9547609622,Devic
e=virtio-serial,Type=controller,BootOrder=0,SpecParams={},Address=
{bus=0x00, domain=0x0000, type=pci, slot=0x04,
function=0x0},IsManaged=false,IsPlugged=true,IsReadOnly=false,alias=virtio-serial0,
device_bb912edd-9790-43ff-a758-f1d9f20cb5f5device_f5c86859-5ae9-4a37-9d34-2b9547609622device_20a11f26-6a39-415d-a7bf-95893b9c55b5device_21f255dc-9b3b-48d8-b8e4-63c1635e269b=VmId=509e608c-e657-473a-b031-f0811da96bde,DeviceId=21f255dc-9b3b-48d8-b8e4-63c1635e269b,Device=spicevmc,Type=channel,BootOrder=0,SpecP
arams={},Address={port=2, bus=0, controller=0,
type=virtio-serial},IsManaged=false,IsPlugged=true,IsReadOnly=false,alias=channel1,
device_bb912edd-9790-43ff-a758-f1d9f20cb5f5device_f5c86859-5ae9-4a37-9d34-2b9547609622device_20a11f26-6a39-415d-a7bf-95893b9c55b5device_21f255dc-9b3b-48d8-b8e4-63c1635e269bdevice_d6c2c4d1-da6b-44fe-a5aa-508135c7fdfe=VmId=509e608c-e657-473a-b031-f0811da96bde,DeviceId=d6c2c4d1-da6b-44fe-a5aa-508135c7fdfe,Device=usb,Type=controller,BootOrder=0,SpecParams=
{},Address={bus=0x0 0, domain=0x0000, type=pci,
slot=0x01,
function=0x2},IsManaged=false,IsPlugged=true,IsReadOnly=false,alias=usb0}
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= key: 509e608c-e657-473a-b031-f0811da96bde value: VM
, sharedLocks= ]
2012-09-20 12:42:54,418 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand]
(QuartzScheduler_Worker-12) START, DestroyVDSCommand(vdsId =
0a268762-02d7-11e2-b750-0011856cf23e,
vmId=509e608c-e657-473a-b031-f0811da96bde, force=false, secondsToWait=0,
gracefully=false), 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 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_Worker-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-thread-50) START, UpdateVdsDynamicDataVDSCommand(vdsId =
0a268762-02d7-11e2-b750-0011856cf23e,
vdsDynamic=org.ovirt.engine.core.common.businessentities.VdsDynamic at db702e05),
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: 71c6e6a3
2012-09-20 12:42:54,584 INFO [org.ovirt.engine.core.bll.RunVmCommand]
(pool-3-thread-50) Lock Acquired to object EngineLock [exclusiveLocks= key:
509e608c-e657-473a-b031-f0811da96bde value: VM
, sharedLocks= ]
2012-09-20 12:42:54,603 INFO
[org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand]
(pool-3-thread-50) START, IsValidVDSCommand(storagePoolId =
332694bb-364a-434e-b23f-5fef985d3cbd, ignoreFailoverLimit = false,
compatabilityVersion = 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: f1903fc
2012-09-20 12:42:54,653 INFO
[org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand]
(pool-3-thread-50) START, IsVmDuringInitiatingVDSCommand(vmId =
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: 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)
START, CreateVmVDSCommand(vdsId = 9840e840-02db-11e2-a01a-0011856cf23e,
vmId=509e608c-e657-473a-b031-f0811da96bde,
vm=org.ovirt.engine.core.common.businessentities.VM at 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 =
9840e840-02db-11e2-a01a-0011856cf23e,
vmId=509e608c-e657-473a-b031-f0811da96bde,
vm=org.ovirt.engine.core.common.businessentities.VM at 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=DEFAULT,memSize=1024,kvmEnable=true,smp=1,emulatedMachine=pc-0.14,vmType=kvm,keyboardLayout=en-us,pitReinjection=false,nice=0,display=qxl,smpCoresPerSocket=1,spiceSecureChannels=smain,sinputs,scursor,splayback,srecord,sdisplay,displayNetwork=ovirtmgmt,timeOffset=-1,transparentHugePages=true,vmId=509e608c-e657-473a
-b031-f0811da96bde,devices=
[Ljava.util.Map;@41d42882,acpiEnable=true,vmName=CentOS6Thames,cpuType=Conroe,custom=
{device_bb912edd-9790-43ff-a758-f1d9f20cb5f5device_f5c86859-5ae9-4a37-9d34-2b9547609622device_20a11f26-6a39-415d-a7bf-95893b9c55b5=VmId=509e608c-e657-473a-b031-f0811da96bde,DeviceId=20a11f26-6a39-415d-a7bf-95893b9c55b5,Device=unix,Type=channel,BootOrder=0,SpecParams=
{},Address={port=1, bus=0, controller=0,
type=virtio-serial},IsManaged=false,IsPlugged=true,IsReadOnly=false,alias=channel0,
device_bb912edd-9790-43ff-a758-f1d9f20cb5f5=VmId=509e608c-e657-473a-b031-f0811da96bde,DeviceId=bb912edd-9790-43ff-a758-f1d9f20cb5f5,Device=ide,Type=controller,BootOrder=0,SpecParams=
{},Address={bus=0x00, domain=0x0000, type=pci, slot=0x01,
function=0x1},IsManaged=false,IsPlugged=true,IsReadOnly=false,alias=ide0,
device_bb912edd-9790-43ff-a758-f1d9f20cb5f5device_f5c86859-5ae9-4a37-9d34-2b9547609622=VmId=509e608c-e657-473a-b031-f0811da96bde,DeviceId=f5c86859-5ae9-4a37-9d34-2b9547609622,Device=virtio-s
erial,Type=controller,BootOrder=0,SpecParams=
{},Address={bus=0x00, domain=0x0000, type=pci, slot=0x04,
function=0x0},IsManaged=false,IsPlugged=true,IsReadOnly=false,alias=virtio-serial0,
device_bb912edd-9790-43ff-a758-f1d9f20cb5f5device_f5c86859-5ae9-4a37-9d34-2b9547609622device_20a11f26-6a39-415d-a7bf-95893b9c55b5device_21f255dc-9b3b-48d8-b8e4-63c1635e269b=VmId=509e608c-e657-473a-b031-f0811da96bde,DeviceId=21f255dc-9b3b-48d8-b8e4-63c1635e269b,Device=spicevmc,Type=channel,BootOrder=0,SpecParams=
{},A ddress={port=2, bus=0, controller=0,
type=virtio-serial},IsManaged=false,IsPlugged=true,IsReadOnly=false,alias=channel1,
device_bb912edd-9790-43ff-a758-f1d9f20cb5f5device_f5c86859-5ae9-4a37-9d34-2b9547609622device_20a11f26-6a39-415d-a7bf-95893b9c55b5device_21f255dc-9b3b-48d8-b8e4-63c1635e269bdevice_d6c2c4d1-da6b-44fe-a5aa-508135c7fdfe=VmId=509e608c-e657-473a-b031-f0811da96bde,DeviceId=d6c2c4d1-da6b-44fe-a5aa-508135c7fdfe,Device=usb,Type=controller,BootOrder=0,SpecParams=
{},Address={bus=0x00, domain= 0x0000, type=pci,
slot=0x01,
function=0x2},IsManaged=false,IsPlugged=true,IsReadOnly=false,alias=usb0}
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 vcpu
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= key:
509e608c-e657-473a-b031-f0811da96bde value: VM
, sharedLocks= ]
2012-09-20 12:42:56,434 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand]
(QuartzScheduler_Worker-32) START, DestroyVDSCommand(vdsId =
9840e840-02db-11e2-a01a-0011856cf23e,
vmId=509e608c-e657-473a-b031-f0811da96bde, force=false, secondsToWait=0,
gracefully=false), 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 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_Worker-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-thread-50) START, UpdateVdsDynamicDataVDSCommand(vdsId =
9840e840-02db-11e2-a01a-0011856cf23e,
vdsDynamic=org.ovirt.engine.core.common.businessentities.VdsDynamic at 5f1dd7c7),
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: 2a191f9e
2012-09-20 12:42:56,616 INFO [org.ovirt.engine.core.bll.RunVmCommand]
(pool-3-thread-50) Lock Acquired to object EngineLock [exclusiveLocks= key:
509e608c-e657-473a-b031-f0811da96bde value: VM
, sharedLocks= ]
2012-09-20 12:42:56,632 INFO
[org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand]
(pool-3-thread-50) START, IsValidVDSCommand(storagePoolId =
332694bb-364a-434e-b23f-5fef985d3cbd, ignoreFailoverLimit = false,
compatabilityVersion = 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 =
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: 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 object EngineLock [exclusiveLocks= key:
509e608c-e657-473a-b031-f0811da96bde value: VM
, sharedLocks= ]
vdsm.log:
Dummy-1960::DEBUG::2012-09-20
06:46:58,959::__init__::1249::Storage.Misc.excCmd::(_log) 'dd
if=/rhev/data-center/332694bb-364a-434e-b23f-5fef985d3cbd/mastersd/dom_md/inbox
iflag=direct,fullblock count=1 bs=1024000' (cwd None)
Dummy-1960::DEBUG::2012-09-20
06:46:59,043::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> =
'1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0488089
s, 21.0 MB/s\n'; <rc> = 0
Dummy-1960::DEBUG::2012-09-20
06:47:01,053::__init__::1249::Storage.Misc.excCmd::(_log) 'dd
if=/rhev/data-center/332694bb-364a-434e-b23f-5fef985d3cbd/mastersd/dom_md/inbox
iflag=direct,fullblock count=1 bs=1024000' (cwd None)
Dummy-1960::DEBUG::2012-09-20
06:47:01,136::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> =
'1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0477826
s, 21.4 MB/s\n'; <rc> = 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_21f255dc-9b3b-48d8-b8e4-63c1635e269bdevice_d6c2c4d1-da6b-44fe-a5aa-508135c7fdfe':
'VmId=509e608c-e657-473a-b031-f0811da96bde,DeviceId=d6c2c4d1-da6b-44fe-a5aa-508135c7fdfe,Device=usb,Type=controller,BootOrder=0,SpecParams=
{},Address={bus=0x00, domain=0x0000, type=pci, slot=0x01,
function=0x2},IsManaged=false,IsPlugged=true,IsReadOnly=false,alias=usb0',
'device_bb912edd-9790-43ff-a758-f1d9f20cb5f5device_f5c86859-5ae9-4a37-9d34-2b9547609622device_20a11f26-6a39-415d-a7bf-95893b9c55b5device_21f255dc-9b3b-48d8-b8e4-63c1635e269b':
'VmId=509e608c-e657-473a-b031-f0811da96bde,DeviceId=21f255dc-9b3b-48d8-b8e4-63c1635e269b,Device=spicevmc,Type=channel,BootOrder=0,SpecParams=
{},Address={port=2, bus=0, controller=0,
type=virtio-serial},IsManaged=false,IsPlugged=true,IsReadOnly=false,alias=channel1',
'device_bb912edd-9790-43ff-a758-f1d9f20cb5f5device_f5c86859-5ae9-4a37-9d34-2b9547609622':
'VmId=509e608c-e657-473a-b031-f0811da96bde,DeviceId=f5c86859-5ae9-4a37-9d34-2b9547609622,Device=virtio-serial,Type=controller,BootOrder=0,SpecParams=
{},Address={bus=0x00, domain=0x0000, type=pci, slot=0x04,
function=0x0},IsManaged=false,IsPlugged=true,IsReadOnly=false,alias=virtio-serial0',
'device_bb912edd-9790-43ff-a758-f1d9f20cb5f5device_f5c86859-5ae9-4a37-9d34-2b9547609622device_20a11f26-6a39-415d-a7bf-95893b9c55b5':
'VmId=509e608c-e657-473a-b031-f0811da96bde,DeviceId=20a11f26-6a39-415d-a7bf-95893b9c55b5,Device=unix,Type=channel,BootOrder=0,SpecParams=
{},Address={port=1, bus=0, controller=0,
type=virtio-serial},IsManaged=false,IsPlugged=true,IsReadOnly=false,alias=channel0',
'device_bb912edd-9790-43ff-a758-f1d9f20cb5f5':
'VmId=509e608c-e657-473a-b031-f0811da96bde,DeviceId=bb912edd-9790-43ff-a758-f1d9f20cb5f5,Device=ide,Type=controller,BootOrder=0,SpecParams=
{},Address={bus=0x00, domain=0x0000, type=pci, slot=0x01,
function=0x1},IsManaged=false,IsPlugged=true,IsReadOnly=false,alias=ide0'},
'keyboardLayout': 'en-us', 'kvmEnable': 'true', 'pitReinjection': 'false',
'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', ' 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', ' 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',
'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', ' 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', '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=`509e608c-e657-473a-b031-f0811da96bde`::Start
Thread-7807::DEBUG::2012-09-20 06:47:01,996::API::244::vds::(create) Total
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=`509e608c-e657-473a-b031-f0811da96bde`::_ongoingCreations acquired
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_21f255dc-9b3b-48d8-b8e4-63c1635e269bdevice_d6c2c4d1-da6b-44fe-a5aa-508135c7fdfe':
'VmId=509e608c-e657-473a-b031-f0811da96bde,DeviceId=d6c2c4d1-da6b-44fe-a5aa-508135c7fdfe,Device=usb,Type=controller,BootOrder=0,SpecParams=
{},Address={bus=0x00, domain=0x0000, type=pci, slot=0x01,
function=0x2},IsManaged=false,IsPlugged=true,IsReadOnly=false,alias=usb0',
'device_bb912edd-9790-43ff-a758-f1d9f20cb5f5device_f5c86859-5ae9-4a37-9d34-2b9547609622device_20a11f26-6a39-415d-a7bf-95893b9c55b5device_21f255dc-9b3b-48d8-b8e4-63c1635e269b':
'VmId=509e608c-e657-473a-b031-f0811da96bde,DeviceId=21f255dc-9b3b-48d8-b8e4-63c1635e269b,Device=spicevmc,Type=channel,BootOrder=0,SpecParams=
{},Address={port=2, bus=0, controller=0,
type=virtio-serial},IsManaged=false,IsPlugged=true,IsReadOnly=false,alias=channel1',
'device_bb912edd-9790-43ff-a758-f1d9f20cb5f5device_f5c86859-5ae9-4a37-9d34-2b9547609622':
'VmId=509e608c-e657-473a-b031-f0811da96bde,DeviceId=f5c86859-5ae9-4a37-9d34-2b9547609622,Device=virtio-serial,Type=controller,BootOrder=0,SpecParams=
{},Address={bus=0x00, domain=0x0000, type=pci, slot=0x04,
function=0x0},IsManaged=false,IsPlugged=true,IsReadOnly=false,alias=virtio-serial0',
'device_bb912edd-9790-43ff-a758-f1d9f20cb5f5device_f5c86859-5ae9-4a37-9d34-2b9547609622device_20a11f26-6a39-415d-a7bf-95893b9c55b5':
'VmId=509e608c-e657-473a-b031-f0811da96bde,DeviceId=20a11f26-6a39-415d-a7bf-95893b9c55b5,Device=unix,Type=channel,BootOrder=0,SpecParams=
{},Address={port=1, bus=0, controller=0,
type=virtio-serial},IsManaged=false,IsPlugged=true,IsReadOnly=false,alias=channel0',
'device_bb912edd-9790-43ff-a758-f1d9f20cb5f5':
'VmId=509e608c-e657-473a-b031-f0811da96bde,DeviceId=bb912edd-9790-43ff-a758-f1d9f20cb5f5,Device=ide,Type=controller,BootOrder=0,SpecParams=
{},Address={bus=0x00, domain=0x0000, type=pci, slot=0x01,
function=0x1},IsManaged=false,IsPlugged=true,IsReadOnly=false,alias=ide0'},
'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', ' slot':
'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', ' 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',
'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::(_run)
vmId=`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=`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='26187d25-bfcb-40c7-97d1-667705ad2223',
spUUID='332694bb-364a-434e-b23f-5fef985d3cbd',
imgUUID='0a7013db-68fd-4c42-bc2e-cc8d7a05ca18',
volUUID='f184ecd1-0001-4739-af71-250b412345d6', options=None)
Thread-7808::DEBUG::2012-09-20
06:47:02,001::resourceManager::175::ResourceManager.Request::(__init__)
ResName=`Storage.26187d25-bfcb-40c7-97d1-667705ad2223`ReqID=`83dac2e0-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-667705ad2223'
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=`Storage.26187d25-bfcb-40c7-97d1-667705ad2223`ReqID=`83dac2e0-3d55-4ef6-abf3-7b2561814ab4`::Granted
request
Thread-7808::DEBUG::2012-09-20
06:47:02,003::task::817::TaskManager.Task::(resourceAcquired)
Task=`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=`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', 'apparentsize':
'13958643712'}
Thread-7808::DEBUG::2012-09-20
06:47:02,004::task::1172::TaskManager.Task::(prepare)
Task=`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=`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)
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-667705ad2223'
Thread-7808::DEBUG::2012-09-20
06:47:02,005::resourceManager::553::ResourceManager::(releaseResource)
Released resource 'Storage.26187d25-bfcb-40c7-97d1-667705ad2223' (0 active
users)
Thread-7808::DEBUG::2012-09-20
06:47:02,005::resourceManager::558::ResourceManager::(releaseResource)
Resource 'Storage.26187d25-bfcb-40c7-97d1-667705ad2223' is free, finding
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-667705ad2223',
Clearing records.
Thread-7808::DEBUG::2012-09-20
06:47:02,005::task::978::TaskManager.Task::(_decref)
Task=`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 path:
Thread-7808::DEBUG::2012-09-20
06:47:02,006::task::588::TaskManager.Task::(_updateState)
Task=`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='26187d25-bfcb-40c7-97d1-667705ad2223',
spUUID='332694bb-364a-434e-b23f-5fef985d3cbd',
imgUUID='0a7013db-68fd-4c42-bc2e-cc8d7a05ca18',
volUUID='f184ecd1-0001-4739-af71-250b412345d6')
Thread-7808::DEBUG::2012-09-20
06:47:02,007::resourceManager::175::ResourceManager.Request::(__init__)
ResName=`Storage.26187d25-bfcb-40c7-97d1-667705ad2223`ReqID=`c22e6209-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-667705ad2223'
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=`Storage.26187d25-bfcb-40c7-97d1-667705ad2223`ReqID=`c22e6209-b86d-448c-8884-372ce9a589c4`::Granted
request
Thread-7808::DEBUG::2012-09-20
06:47:02,008::task::817::TaskManager.Task::(resourceAcquired)
Task=`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=`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=direct skip=4 bs=512
if=/dev/26187d25-bfcb-40c7-97d1-667705ad2223/metadata count=1' (cwd None)
Thread-7808::DEBUG::2012-09-20
06:47:02,023::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> =
'1+0 records in\n1+0 records out\n512 bytes (512 B) copied, 0.000766795 s,
668 kB/s\n'; <rc> = 0
Thread-7808::DEBUG::2012-09-20
06:47:02,023::misc::314::Storage.Misc::(validateDDBytes) err: ['1+0 records
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=26187d25-bfcb-40c7-97d1-667705ad2223
imgUUID=0a7013db-68fd-4c42-bc2e-cc8d7a05ca18 chain=
[<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-40c7-97d1-667705ad2223/images/0a7013db-68fd-4c42-bc2e-cc8d7a05ca18/f184ecd1-0001-4739-af71-250b412345d6',
'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-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=`83579cfe-4384-4b76-8bb0-979ed2b60739`::finished: {'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',
'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-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=`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)
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-667705ad2223'
Thread-7808::DEBUG::2012-09-20
06:47:02,025::resourceManager::553::ResourceManager::(releaseResource)
Released resource 'Storage.26187d25-bfcb-40c7-97d1-667705ad2223' (0 active
users)
Thread-7808::DEBUG::2012-09-20
06:47:02,026::resourceManager::558::ResourceManager::(releaseResource)
Resource 'Storage.26187d25-bfcb-40c7-97d1-667705ad2223' is free, finding
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-667705ad2223',
Clearing records.
Thread-7808::DEBUG::2012-09-20
06:47:02,026::task::978::TaskManager.Task::(_decref)
Task=`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-bfcb-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=`509e608c-e657-473a-b031-f0811da96bde`::<?xml version="1.0"
encoding="utf-8"?>
<domain type="kvm">
<name>CentOS6Thames</name>
<uuid>509e608c-e657-473a-b031-f0811da96bde</uuid>
<memory>1048576</memory>
<currentMemory>1048576</currentMemory>
<vcpu>1</vcpu>
<devices>
<channel type="unix">
<target name="com.redhat.rhevm.vdsm"
type="virtio"/>
<source mode="bind"
path="/var/lib/libvirt/qemu/channels/CentOS6Thames.com.redhat.rhevm.vdsm"/>
</channel>
<input bus="ps2" type="mouse"/>
<channel type="spicevmc">
<target name="com.redhat.spice.0" type="virtio"/>
</channel>
<graphics autoport="yes" keymap="en-us" passwd="*****"
passwdValidTo="1970-01-01T00:00:01" port="-1" tlsPort="-1" type="spice">
<channel mode="secure" name="main"/>
<channel mode="secure" name="inputs"/>
<channel mode="secure" name="cursor"/>
<channel mode="secure" name="playback"/>
<channel mode="secure" name="record"/>
<channel mode="secure" name="display"/>
<listen network="vdsm-ovirtmgmt" type="network"/>
</graphics>
<console type="pty">
<target port="0" type="virtio"/>
</console>
<controller type="usb">
<address domain="0x0000" function="0x2"
slot="0x01" type="pci" bus="0x00"/>
</controller>
<video>
<address domain="0x0000" function="0x0"
slot="0x02" type="pci" bus="0x00"/>
<model heads="1" type="qxl" vram="65536"/>
</video>
<interface type="bridge">
<address domain="0x0000" function="0x0"
slot="0x03" type="pci" bus="0x00"/>
<mac address="00:1a:4a:a8:0a:00"/>
<model type="virtio"/>
<source bridge="ovirtmgmt"/>
</interface>
<memballoon model="virtio"/>
<disk device="cdrom" snapshot="no" type="file">
<address bus="1" controller="0" target="0"
type="drive" unit="0"/>
<source file="" startupPolicy="optional"/>
<target bus="ide" dev="hdc"/>
<readonly/>
<serial></serial>
</disk>
<disk device="disk" snapshot="no" type="block">
<address domain="0x0000" function="0x0"
slot="0x05" type="pci" bus="0x00"/>
<source
dev="/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="virtio" dev="vda"/>
<serial>0a7013db-68fd-4c42-bc2e-cc8d7a05ca18</serial>
<driver cache="none" error_policy="stop"
io="native" name="qemu" type="qcow2"/>
</disk>
</devices>
<os>
<type arch="x86_64" machine="pc-0.14">hvm</type>
<smbios mode="sysinfo"/>
</os>
<sysinfo type="smbios">
<system>
<entry name="manufacturer">Red Hat</entry>
<entry name="product">RHEV Hypervisor</entry>
<entry name="version">17-1</entry>
<entry
name="serial">31323334-3535-4C44-3643-4D5633393936_00:19:bb:39:97:4a</entry>
<entry
name="uuid">509e608c-e657-473a-b031-f0811da96bde</entry>
</system>
</sysinfo>
<clock adjustment="-1" offset="variable">
<timer name="rtc" tickpolicy="catchup"/>
</clock>
<features>
<acpi/>
</features>
<cpu match="exact">
<model>Conroe</model>
<topology cores="1" sockets="1" threads="1"/>
</cpu>
</domain>
Thread-7808::DEBUG::2012-09-20
06:47:02,426::vm::580::vm.Vm::(_startUnderlyingVm)
vmId=`509e608c-e657-473a-b031-f0811da96bde`::_ongoingCreations released
Thread-7808::ERROR::2012-09-20
06:47:02,427::vm::604::vm.Vm::(_startUnderlyingVm)
vmId=`509e608c-e657-473a-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/libvirtvm.py", line 1364, in _run
File "/usr/lib/python2.7/site-packages/vdsm/libvirtconnection.py", line
82, in wrapper
File "/usr/lib64/python2.7/site-packages/libvirt.py", line 2420, in
createXML
libvirtError: unsupported configuration: spice secure channels set in XML
configuration, but TLS is disabled in qemu.conf
Thread-7808::DEBUG::2012-09-20
06:47:02,430::vm::920::vm.Vm::(setDownStatus)
vmId=`509e608c-e657-473a-b031-f0811da96bde`::Changed state to Down:
unsupported configuration: spice secure channels set in XML configuration,
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=/rhev/data-center/332694bb-364a-434e-b23f-5fef985d3cbd/mastersd/dom_md/inbox
iflag=direct,fullblock count=1 bs=1024000' (cwd None)
Dummy-1960::DEBUG::2012-09-20
06:47:03,230::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> =
'1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0496138
s, 20.6 MB/s\n'; <rc> = 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=`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='332694bb-364a-434e-b23f-5fef985d3cbd', options=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': 'SPM',
'spmLver': 0}}
Thread-7810::DEBUG::2012-09-20
06:47:03,562::task::1172::TaskManager.Task::(prepare)
Task=`9bc08c7e-010f-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=`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)
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=`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=`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='332694bb-364a-434e-b23f-5fef985d3cbd',
options=None)
Thread-7812::DEBUG::2012-09-20
06:47:03,596::resourceManager::175::ResourceManager.Request::(__init__)
ResName=`Storage.332694bb-364a-434e-b23f-5fef985d3cbd`ReqID=`a7222834-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-5fef985d3cbd'
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=`Storage.332694bb-364a-434e-b23f-5fef985d3cbd`ReqID=`a7222834-3565-4e28-a15f-72692ef664c6`::Granted
request
Thread-7812::DEBUG::2012-09-20
06:47:03,597::task::817::TaskManager.Task::(resourceAcquired)
Task=`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=`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_uuid':
'26187d25-bfcb-40c7-97d1-667705ad2223', 'name': 'Valeka', 'version': '2',
'domains':
u'26187d25-bfcb-40c7-97d1-667705ad2223:Active,90104c3d-837b-47dd-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-bfcb-40c7-97d1-667705ad2223': {'status': u'Active', 'diskfree':
'1674097721344', 'alerts': [], 'disktotal': '1799591297024'},
u'90104c3d-837b-47dd-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',
'exitCode': 1}]}
Thread-7812::DEBUG::2012-09-20
06:47:03,600::task::1172::TaskManager.Task::(prepare)
Task=`8e330204-753f-422d-b286-a360410806be`::finished: {'info': {'spm_id':
3, 'master_uuid': '26187d25-bfcb-40c7-97d1-667705ad2223', 'name': 'Valeka',
'version': '2', 'domains':
u'26187d25-bfcb-40c7-97d1-667705ad2223:Active,90104c3d-837b-47dd-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-bfcb-40c7-97d1-667705ad2223': {'status': u'Active', 'diskfree':
'1674097721344', 'alerts': [], 'disktotal': '1799591297024'},
u'90104c3d-837b-47dd-8c82-dda92eec30d9': {'status': u'Active', 'diskfree':
'423518535680', 'alerts': [], 'disktotal': '492264226816'}}}
Thread-7812::DEBUG::2012-09-20
06:47:03,601::task::588::TaskManager.Task::(_updateState)
Task=`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)
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-5fef985d3cbd'
Thread-7812::DEBUG::2012-09-20
06:47:03,602::resourceManager::553::ResourceManager::(releaseResource)
Released resource 'Storage.332694bb-364a-434e-b23f-5fef985d3cbd' (0 active
users)
Thread-7812::DEBUG::2012-09-20
06:47:03,602::resourceManager::558::ResourceManager::(releaseResource)
Resource 'Storage.332694bb-364a-434e-b23f-5fef985d3cbd' is free, finding
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-5fef985d3cbd',
Clearing records.
Thread-7812::DEBUG::2012-09-20
06:47:03,602::task::978::TaskManager.Task::(_decref)
Task=`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=`509e608c-e657-473a-b031-f0811da96bde`::destroy Called
Thread-7814::INFO::2012-09-20
06:47:03,658::libvirtvm::2040::vm.Vm::(releaseVm)
vmId=`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=`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/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> =
'Redirecting to /bin/systemctl retune ksmtuned.service\nUnknown operation
retune\n'; <rc> = 1
Thread-7814::DEBUG::2012-09-20
06:47:03,697::task::588::TaskManager.Task::(_updateState)
Task=`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='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=`e97820bb-547d-4e7a-9249-ece94285bac8`::finished: None
Thread-7814::DEBUG::2012-09-20
06:47:03,700::task::588::TaskManager.Task::(_updateState)
Task=`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)
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=`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=`509e608c-e657-473a-b031-f0811da96bde`::Total desktops after destroy
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=direct if=/dev/26187d25-bfcb-40c7-97d1-667705ad2223/metadata bs=4096
count=1' (cwd None)
Thread-481::DEBUG::2012-09-20
06:47:04,317::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> =
'1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000843551
s, 4.9 MB/s\n'; <rc> = 0
Dummy-1960::DEBUG::2012-09-20
06:47:05,239::__init__::1249::Storage.Misc.excCmd::(_log) 'dd
if=/rhev/data-center/332694bb-364a-434e-b23f-5fef985d3cbd/mastersd/dom_md/inbox
iflag=direct,fullblock count=1 bs=1024000' (cwd None)
Dummy-1960::DEBUG::2012-09-20
06:47:05,323::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> =
'1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0476578
s, 21.5 MB/s\n'; <rc> = 0
Thread-7815::DEBUG::2012-09-20
06:47:05,819::task::588::TaskManager.Task::(_updateState)
Task=`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=None)
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=`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=`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)
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=`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=/rhev/data-center/332694bb-364a-434e-b23f-5fef985d3cbd/mastersd/dom_md/inbox
iflag=direct,fullblock count=1 bs=1024000' (cwd None)
Dummy-1960::DEBUG::2012-09-20
06:47:07,458::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> =
'1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0478973
s, 21.4 MB/s\n'; <rc> = 0
Dummy-1960::DEBUG::2012-09-20
06:47:09,502::__init__::1249::Storage.Misc.excCmd::(_log) 'dd
if=/rhev/data-center/332694bb-364a-434e-b23f-5fef985d3cbd/mastersd/dom_md/inbox
iflag=direct,fullblock count=1 bs=1024000' (cwd None)
Dummy-1960::DEBUG::2012-09-20
06:47:09,586::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> =
'1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0485543
s, 21.1 MB/s\n'; <rc> = 0
If I try to create new server I have the same error message.
- -
Dmitriy Pyryakov
VimpelCom Ltd.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.ovirt.org/pipermail/users/attachments/20120920/b7258224/attachment.html>
More information about the Users
mailing list