8:47 a.m.
--========GMXBoundary242171385563631782200
Content-Type: text/plain; charset="utf-8"
Content-Transfer-Encoding: 8bit
Hello,
I'm running in troubles.....
After migrating the storage of an powered off VM to a different iSCSI storage, my CentOS 4
VM does not start any more (well, it's not the reality, but for the system the VM
stays in Wait for launch for hours). In reality, the VM starts on the node.
Any hints?
My Config:
CentOS 6.4
oVirt 3.3.1-2
VDSM 4.12.1-4
engine.log
2013-11-26 14:58:50,171 INFO [org.ovirt.engine.core.bll.AsyncTaskManager]
(DefaultQuartzScheduler_Worker-46) Setting new tasks map. The map contains now 0 tasks
2013-11-26 14:58:50,172 INFO [org.ovirt.engine.core.bll.AsyncTaskManager]
(DefaultQuartzScheduler_Worker-46) Cleared all tasks of pool
5849b030-626e-47cb-ad90-3ce782d831b3.
2013-11-26 14:58:52,106 INFO [org.ovirt.engine.core.bll.RunVmCommand]
(ajp--127.0.0.1-8702-2) [574ec4d2] Lock Acquired to object EngineLock [exclusiveLocks=
key: 8798d0da-a82c-4bcf-b41a-7e3fe1c613ef value: VM
, sharedLocks= ]
2013-11-26 14:58:52,124 INFO
[org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (ajp--127.0.0.1-8702-2)
[574ec4d2] START, IsVmDuringInitiatingVDSCommand( vmId =
8798d0da-a82c-4bcf-b41a-7e3fe1c613ef), log id: 13e7aadf
2013-11-26 14:58:52,125 INFO
[org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (ajp--127.0.0.1-8702-2)
[574ec4d2] FINISH, IsVmDuringInitiatingVDSCommand, return: false, log id: 13e7aadf
2013-11-26 14:58:52,251 INFO [org.ovirt.engine.core.bll.RunVmCommand] (pool-6-thread-50)
[574ec4d2] Running command: RunVmCommand internal: false. Entities affected : ID:
8798d0da-a82c-4bcf-b41a-7e3fe1c613ef Type: VM
2013-11-26 14:58:52,406 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.IsoPrefixVDSCommand] (pool-6-thread-50)
[574ec4d2] START, IsoPrefixVDSCommand(HostName = HOST01, HostId =
b34d1e33-bdda-4ba8-9c23-0d136f372ad8, storagePoolId=5849b030-626e-47cb-ad90-3ce782d831b3),
log id: 1a6a3b22
2013-11-26 14:58:52,408 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.IsoPrefixVDSCommand] (pool-6-thread-50)
[574ec4d2] FINISH, IsoPrefixVDSCommand, return:
/rhev/data-center/mnt/engine.private.com:_var_lib_exports_iso/53a22027-fd2d-451b-8cd7-0e604fb8e460/images/11111111-1111-1111-1111-111111111111,
log id: 1a6a3b22
2013-11-26 14:58:52,441 INFO [org.ovirt.engine.core.vdsbroker.CreateVmVDSCommand]
(pool-6-thread-50) [574ec4d2] START, CreateVmVDSCommand(HostName = HOST01, HostId =
b34d1e33-bdda-4ba8-9c23-0d136f372ad8, vmId=8798d0da-a82c-4bcf-b41a-7e3fe1c613ef, vm=VM
[vm01]), log id: 2da012df
2013-11-26 14:58:52,476 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand]
(pool-6-thread-50) [574ec4d2] START, CreateVDSCommand(HostName = HOST01, HostId =
b34d1e33-bdda-4ba8-9c23-0d136f372ad8, vmId=8798d0da-a82c-4bcf-b41a-7e3fe1c613ef, vm=VM
[vm01]), log id: 727a7bf7
2013-11-26 14:58:52,539 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand]
(pool-6-thread-50) [574ec4d2] org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand
spiceSslCipherSuite=DEFAULT,memSize=1024,kvmEnable=true,smp=1,vmType=kvm,emulatedMachine=rhel6.4.0,keyboardLayout=de,memGuaranteedSize=512,pitReinjection=false,nice=0,display=vnc,smartcardEnable=false,tabletEnable=true,smpCoresPerSocket=1,spiceSecureChannels=smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard,timeOffset=1,transparentHugePages=true,vmId=8798d0da-a82c-4bcf-b41a-7e3fe1c613ef,devices=[Ljava.util.HashMap;@1030ba06,acpiEnable=true,vmName=vm01,cpuType=Nehalem,custom={device_99b583e9-9030-40af-bb41-55d62a4a6b6adevice_5b94ca77-fab8-41b4-b286-311dee724813=VmDevice
{vmId=8798d0da-a82c-4bcf-b41a-7e3fe1c613ef, deviceId=5b94ca77-fab8-41b4-b286-311dee724813,
device=unix, type=CHANNEL, bootOrder=0, specParams={}, address={port=2, bus=0,
controller=0, type=virtio-serial}, managed=false, plugged=true, readOnly=false,
deviceAlias=channel1, customProperties={}},
device_99b583e9-9030-40af-bb41-55d62a4a6b6a=VmDevice
{vmId=8798d0da-a82c-4bcf-b41a-7e3fe1c613ef, deviceId=99b583e9-9030-40af-bb41-55d62a4a6b6a,
device=unix, type=CHANNEL, bootOrder=0, specParams={}, address={port=1, bus=0,
controller=0, type=virtio-serial}, managed=false, plugged=true, readOnly=false,
deviceAlias=channel0, customProperties={}},
device_99b583e9-9030-40af-bb41-55d62a4a6b6adevice_5b94ca77-fab8-41b4-b286-311dee724813device_c3d8dcbf-d977-4d4d-8240-35b973ee00b9device_839371b0-1967-4435-910e-0d8e1c980850=VmDevice
{vmId=8798d0da-a82c-4bcf-b41a-7e3fe1c613ef, deviceId=839371b0-1967-4435-910e-0d8e1c980850,
device=ide, type=CONTROLLER, bootOrder=0, specParams={}, address={bus=0x00, domain=0x0000,
type=pci, slot=0x01, function=0x1}, managed=false, plugged=true, readOnly=false,
deviceAlias=ide0, customProperties={}},
device_99b583e9-9030-40af-bb41-55d62a4a6b6adevice_5b94ca77-fab8-41b4-b286-311dee724813device_c3d8dcbf-d977-4d4d-8240-35b973ee00b9=VmDevice
{vmId=8798d0da-a82c-4bcf-b41a-7e3fe1c613ef, deviceId=c3d8dcbf-d977-4d4d-8240-35b973ee00b9,
device=scsi, type=CONTROLLER, bootOrder=0, specParams={}, address={bus=0x00,
domain=0x0000, type=pci, slot=0x04, function=0x0}, managed=false, plugged=true,
readOnly=false, deviceAlias=scsi0, customProperties={}},
device_99b583e9-9030-40af-bb41-55d62a4a6b6adevice_5b94ca77-fab8-41b4-b286-311dee724813device_c3d8dcbf-d977-4d4d-8240-35b973ee00b9device_839371b0-1967-4435-910e-0d8e1c980850device_920282ca-79c2-4abf-b1f2-7425f16f7820=VmDevice
{vmId=8798d0da-a82c-4bcf-b41a-7e3fe1c613ef, deviceId=920282ca-79c2-4abf-b1f2-7425f16f7820,
device=virtio-serial, type=CONTROLLER, bootOrder=0, specParams={}, address={bus=0x00,
domain=0x0000, type=pci, slot=0x06, function=0x0}, managed=false, plugged=true,
readOnly=false, deviceAlias=virtio-serial0, customProperties={}}}
2013-11-26 14:58:52,552 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand]
(pool-6-thread-50) [574ec4d2] FINISH, CreateVDSCommand, log id: 727a7bf7
2013-11-26 14:58:52,567 INFO [org.ovirt.engine.core.vdsbroker.CreateVmVDSCommand]
(pool-6-thread-50) [574ec4d2] FINISH, CreateVmVDSCommand, return: WaitForLaunch, log id:
2da012df
2013-11-26 14:58:52,568 INFO [org.ovirt.engine.core.bll.RunVmCommand] (pool-6-thread-50)
[574ec4d2] Lock freed to object EngineLock [exclusiveLocks= key:
8798d0da-a82c-4bcf-b41a-7e3fe1c613ef value: VM
, sharedLocks= ]
2013-11-26 14:58:52,576 INFO
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (pool-6-thread-50)
[574ec4d2] Correlation ID: 574ec4d2, Job ID: d3d270e1-607b-4599-983a-1ef884e81a43, Call
Stack: null, Custom Event ID: -1, Message: VM vm01 was started by User01 (Host: HOST01).
2013-11-26 14:58:55,177 WARN [org.ovirt.engine.core.vdsbroker.VdsManager]
(DefaultQuartzScheduler_Worker-33) Failed to refresh VDS , vds =
b34d1e33-bdda-4ba8-9c23-0d136f372ad8 : HOST01, error = java.lang.NullPointerException,
continuing.: java.lang.NullPointerException
at
org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo.proceedBalloonCheck(VdsUpdateRunTimeInfo.java:1312)
[vdsbroker.jar:]
at
org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo.refreshVmStats(VdsUpdateRunTimeInfo.java:926)
[vdsbroker.jar:]
at
org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo.refreshVdsRunTimeInfo(VdsUpdateRunTimeInfo.java:502)
[vdsbroker.jar:]
at
org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo.Refresh(VdsUpdateRunTimeInfo.java:343)
[vdsbroker.jar:]
at org.ovirt.engine.core.vdsbroker.VdsManager.OnTimer(VdsManager.java:237)
[vdsbroker.jar:]
at sun.reflect.GeneratedMethodAccessor9.invoke(Unknown Source) [:1.7.0_45]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[rt.jar:1.7.0_45]
at java.lang.reflect.Method.invoke(Method.java:606) [rt.jar:1.7.0_45]
at org.ovirt.engine.core.utils.timer.JobWrapper.execute(JobWrapper.java:60)
[scheduler.jar:]
at org.quartz.core.JobRunShell.run(JobRunShell.java:213) [quartz.jar:]
at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:557)
[quartz.jar:]
vdsm.log
Thread-867485::DEBUG::2013-11-26 14:58:52,504::BindingXMLRPC::979::vds::(wrapper) client
[192.168.1.29]::call vmCreate with ({'acpiEnable': 'true',
'emulatedMachine': 'rhel6.4.0', 'tabletEnable': 'true',
'vmId': '8798d0da-a82c-4bcf-b41a-7e3fe1c613ef',
'memGuaranteedSize': 512, 'spiceSslCipherSuite': 'DEFAULT',
'timeOffset': '1', 'cpuType': 'Nehalem', 'custom':
{'device_99b583e9-9030-40af-bb41-55d62a4a6b6adevice_5b94ca77-fab8-41b4-b286-311dee724813device_c3d8dcbf-d977-4d4d-8240-35b973ee00b9':
'VmDevice {vmId=8798d0da-a82c-4bcf-b41a-7e3fe1c613ef,
deviceId=c3d8dcbf-d977-4d4d-8240-35b973ee00b9, device=scsi, type=CONTROLLER, bootOrder=0,
specParams={}, address={bus=0x00, domain=0x0000, type=pci, slot=0x04, function=0x0},
managed=false, plugged=true, readOnly=false, deviceAlias=scsi0, customProperties={}}',
'device_99b583e9-9030-40af-bb41-55d62a4a6b6a': 'VmDevice
{vmId=8798d0da-a82c-4bcf-b41a-7e3fe1c613ef, deviceId=99b583e9-9030-40af-bb41-55d62a4a6b6a,
device=unix, type=CHANNEL, bootOrder=0, specParams={}, address={port=1, bus=0,
controller=0, type=virtio-serial}, managed=false, plugged=true, readOnly=false,
deviceAlias=channel0, customProperties={}}',
'device_99b583e9-9030-40af-bb41-55d62a4a6b6adevice_5b94ca77-fab8-41b4-b286-311dee724813device_c3d8dcbf-d977-4d4d-8240-35b973ee00b9device_839371b0-1967-4435-910e-0d8e1c980850device_920282ca-79c2-4abf-b1f2-7425f16f7820':
'VmDevice {vmId=8798d0da-a82c-4bcf-b41a-7e3fe1c613ef,
deviceId=920282ca-79c2-4abf-b1f2-7425f16f7820, device=virtio-serial, type=CONTROLLER,
bootOrder=0, specParams={}, address={bus=0x00, domain=0x0000, type=pci, slot=0x06,
function=0x0}, managed=false, plugged=true, readOnly=false, deviceAlias=virtio-serial0,
customProperties={}}',
'device_99b583e9-9030-40af-bb41-55d62a4a6b6adevice_5b94ca77-fab8-41b4-b286-311dee724813device_c3d8dcbf-d977-4d4d-8240-35b973ee00b9device_839371b0-1967-4435-910e-0d8e1c980850':
'VmDevice {vmId=8798d0da-a82c-4bcf-b41a-7e3fe1c613ef,
deviceId=839371b0-1967-4435-910e-0d8e1c980850, device=ide, type=CONTROLLER, bootOrder=0,
specParams={}, address={bus=0x00, domain=0x0000, type=pci, slot=0x01, function=0x1},
managed=false, plugged=true, readOnly=false, deviceAlias=ide0, customProperties={}}',
'device_99b583e9-9030-40af-bb41-55d62a4a6b6adevice_5b94ca77-fab8-41b4-b286-311dee724813':
'VmDevice {vmId=8798d0da-a82c-4bcf-b41a-7e3fe1c613ef,
deviceId=5b94ca77-fab8-41b4-b286-311dee724813, device=unix, type=CHANNEL, bootOrder=0,
specParams={}, address={port=2, bus=0, controller=0, type=virtio-serial}, managed=false,
plugged=true, readOnly=false, deviceAlias=channel1, customProperties={}}'},
'smp': '1', 'vmType': 'kvm', 'memSize': 1024,
'smpCoresPerSocket': '1', 'vmName':
'vm01', 'nice': '0', 'smartcardEnable': 'false',
'keyboardLayout': 'de', 'kvmEnable': 'true',
'pitReinjection': 'false', 'transparentHugePages': 'true',
'devices': [{'device': 'cirrus', 'specParams':
{'vram': '65536'}, 'type': 'video', 'deviceId':
'bf71f555-dc86-417b-9649-b06083b863b8', 'address': {'bus':
'0x00', ' slot': '0x02', ' domain': '0x0000',
' type': 'pci', ' function': '0x0'}}, {'index':
'2', 'iface': 'ide', 'address': {' controller':
'0', ' target': '0', 'unit': '0', ' bus':
'1', ' type': 'drive'}, 'specParams': {'path':
''}, 'readonly': 'true', 'deviceId':
'865f42a1-f64a-49cd-a706-76bc1bea8517', 'path': '',
'device': 'cdrom', 'shared': 'false', 'type':
'disk'}, {'index': 0, 'iface': 'virtio', 'format':
'raw', 'bootOrder': '1', 'poolID':
'5849b030-626e-47cb-ad90-3ce782d831b3', 'volumeID':
'd3011aef-3297-401c-88d7-65079e05dd4d', 'imageID':
'272b7bb5-38e6-41b3-9da4-4cc278873fbf', 'specParams': {},
'readonly': 'false', 'domainID':
'8c8ad4f8-f187-410c-82a7-2beb79a51a30', 'optional': 'false',
'deviceId': '272b7bb5-38e6-41b3-9da4-4cc278873fbf', 'address':
{'bus': '0x00', ' slot': '0x05', ' domain':
'0x0000', ' type': 'pci', ' function': '0x0'},
'device': 'disk', 'shared': 'false',
'propagateErrors': 'off', 'type': 'disk'},
{'nicModel': 'pv', 'macAddr': '52:54:00:6d:ce:c8',
'linkActive': 'true', 'network': 'VM', 'custom':
{}, 'filter': 'vdsm-no-mac-spoofing', 'specParams': {},
'deviceId': '78c714a7-9bc5-464b-85ae-328d29ba0b50', 'address':
{'bus': '0x00', ' slot': '0x03', ' domain':
'0x0000', ' type': 'pci', ' function': '0x0'},
'device': 'bridge', 'type': 'interface'}],
'spiceSecureChannels':
'smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard',
'display': 'vnc'},) {} flowID [574ec4d2]
Thread-867485::INFO::2013-11-26 14:58:52,509::API::641::vds::(_getNetworkIp) network None:
using 0
Thread-867485::INFO::2013-11-26 14:58:52,509::clientIF::366::vds::(createVm)
vmContainerLock acquired by vm 8798d0da-a82c-4bcf-b41a-7e3fe1c613ef
Thread-867485::DEBUG::2013-11-26 14:58:52,515::clientIF::380::vds::(createVm) Total
desktops after creation of 8798d0da-a82c-4bcf-b41a-7e3fe1c613ef is 5
Thread-867486::DEBUG::2013-11-26 14:58:52,516::vm::2015::vm.Vm::(_startUnderlyingVm)
vmId=`8798d0da-a82c-4bcf-b41a-7e3fe1c613ef`::Start
Thread-867485::DEBUG::2013-11-26 14:58:52,516::BindingXMLRPC::986::vds::(wrapper) return
vmCreate with {'status': {'message': 'Done', 'code': 0},
'vmList': {'status': 'WaitForLaunch', 'acpiEnable':
'true', 'emulatedMachine': 'rhel6.4.0', 'tabletEnable':
'true', 'pid': '0', 'memGuaranteedSize': 512,
'timeOffset': '1', 'keyboardLayout': 'de',
'displayPort': '-1', 'displaySecurePort': '-1',
'spiceSslCipherSuite': 'DEFAULT', 'cpuType': 'Nehalem',
'smp': '1', 'clientIp': '', 'nicModel':
'rtl8139,pv', 'smartcardEnable': 'false', 'kvmEnable':
'true', 'pitReinjection': 'false', 'vmId':
'8798d0da-a82c-4bcf-b41a-7e3fe1c613ef', 'transparentHugePages':
'true', 'devices': [{'device': 'cirrus',
'specParams': {'vram': '65536'}, 'type': 'video',
'deviceId': 'bf71f555-dc86-417b-9649-b06083b863b8', 'address':
{'bus': '0x00', ' slot': '0x02', ' domain':
'0x0000', ' type': 'pci', ' function': '0x0'}},
{'index': '2', 'iface': 'ide', 'address': {'
controller': '0', ' target': '0', 'unit': '0',
' bus': '1', ' type': 'drive'}, 'specParams':
{'path': ''}, 'readonly': 'true', 'deviceId':
'865f42a1-f64a-49cd-a706-76bc1bea8517', 'path': '',
'device': 'cdrom', 'shared': 'false', 'type':
'disk'}, {'index': 0, 'iface': 'virtio', 'format':
'raw', 'bootOrder': '1', 'poolID':
'5849b030-626e-47cb-ad90-3ce782d831b3', 'volumeID':
'd3011aef-3297-401c-88d7-65079e05dd4d', 'imageID':
'272b7bb5-38e6-41b3-9da4-4cc278873fbf', 'specParams': {},
'readonly': 'false', 'domainID':
'8c8ad4f8-f187-410c-82a7-2beb79a51a30', 'optional': 'false',
'deviceId': '272b7bb5-38e6-41b3-9da4-4cc278873fbf', 'address':
{'bus': '0x00', ' slot': '0x05', ' domain':
'0x0000', ' type': 'pci', ' function': '0x0'},
'device': 'disk', 'shared': 'false',
'propagateErrors': 'off', 'type': 'disk'},
{'nicModel': 'pv', 'macAddr': '52:54:00:6d:ce:c8',
'linkActive': 'true', 'network': 'VM', 'custom':
{}, 'filter': 'vdsm-no-mac-spoofing', 'specParams': {},
'deviceId': '78c714a7-9bc5-464b-85ae-328d29ba0b50', 'address':
{'bus': '0x00', ' slot': '0x03', ' domain':
'0x0000', ' type': 'pci', ' function': '0x0'},
'device': 'bridge', 'type': 'interface'}],
'custom':
{'device_99b583e9-9030-40af-bb41-55d62a4a6b6adevice_5b94ca77-fab8-41b4-b286-311dee724813device_c3d8dcbf-d977-4d4d-8240-35b973ee00b9':
'VmDevice {vmId=8798d0da-a82c-4bcf-b41a-7e3fe1c613ef,
deviceId=c3d8dcbf-d977-4d4d-8240-35b973ee00b9, device=scsi, type=CONTROLLER, bootOrder=0,
specParams={}, address={bus=0x00, domain=0x0000, type=pci, slot=0x04, function=0x0},
managed=false, plugged=true, readOnly=false, deviceAlias=scsi0, customProperties={}}',
'device_99b583e9-9030-40af-bb41-55d62a4a6b6a': 'VmDevice
{vmId=8798d0da-a82c-4bcf-b41a-7e3fe1c613ef, deviceId=99b583e9-9030-40af-bb41-55d62a4a6b6a,
device=unix, type=CHANNEL, bootOrder=0, specParams={}, address={port=1, bus=0,
controller=0, type=virtio-serial}, managed=false, plugged=true, readOnly=false,
deviceAlias=channel0, customProperties={}}',
'device_99b583e9-9030-40af-bb41-55d62a4a6b6adevice_5b94ca77-fab8-41b4-b286-311dee724813device_c3d8dcbf-d977-4d4d-8240-35b973ee00b9device_839371b0-1967-4435-910e-0d8e1c980850device_920282ca-79c2-4abf-b1f2-7425f16f7820':
'VmDevice {vmId=8798d0da-a82c-4bcf-b41a-7e3fe1c613ef,
deviceId=920282ca-79c2-4abf-b1f2-7425f16f7820, device=virtio-serial, type=CONTROLLER,
bootOrder=0, specParams={}, address={bus=0x00, domain=0x0000, type=pci, slot=0x06,
function=0x0}, managed=false, plugged=true, readOnly=false, deviceAlias=virtio-serial0,
customProperties={}}',
'device_99b583e9-9030-40af-bb41-55d62a4a6b6adevice_5b94ca77-fab8-41b4-b286-311dee724813device_c3d8dcbf-d977-4d4d-8240-35b973ee00b9device_839371b0-1967-4435-910e-0d8e1c980850':
'VmDevice {vmId=8798d0da-a82c-4bcf-b41a-7e3fe1c613ef,
deviceId=839371b0-1967-4435-910e-0d8e1c980850, device=ide, type=CONTROLLER, bootOrder=0,
specParams={}, address={bus=0x00, domain=0x0000, type=pci, slot=0x01, function=0x1},
managed=false, plugged=true, readOnly=false, deviceAlias=ide0, customProperties={}}',
'device_99b583e9-9030-40af-bb41-55d62a4a6b6adevice_5b94ca77-fab8-41b4-b286-311dee724813':
'VmDevice {vmId=8798d0da-a82c-4bcf-b41a-7e3fe1c613ef,
deviceId=5b94ca77-fab8-41b4-b286-311dee724813, device=unix, type=CHANNEL, bootOrder=0,
specParams={}, address={port=2, bus=0, controller=0, type=virtio-serial}, managed=false,
plugged=true, readOnly=false, deviceAlias=channel1, customProperties={}}'},
'vmType': 'kvm', 'memSize': 1024, 'displayIp':
'0', 'spiceSecureChannels':
'smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard',
'smpCoresPerSocket': '1', 'vmName':
'vm01', 'display': 'vnc', 'nice': '0'}}
Thread-867486::DEBUG::2013-11-26 14:58:52,519::vm::2019::vm.Vm::(_startUnderlyingVm)
vmId=`8798d0da-a82c-4bcf-b41a-7e3fe1c613ef`::_ongoingCreations acquired
Thread-867486::INFO::2013-11-26 14:58:52,522::vm::2815::vm.Vm::(_run)
vmId=`8798d0da-a82c-4bcf-b41a-7e3fe1c613ef`::VM wrapper has started
Thread-867486::DEBUG::2013-11-26 14:58:52,527::task::579::TaskManager.Task::(_updateState)
Task=`e64eb271-e389-4057-81f7-1148059464d7`::moving from state init -> state preparing
Thread-867486::INFO::2013-11-26 14:58:52,530::logUtils::44::dispatcher::(wrapper) Run and
protect: getVolumeSize(sdUUID='8c8ad4f8-f187-410c-82a7-2beb79a51a30',
spUUID='5849b030-626e-47cb-ad90-3ce782d831b3',
imgUUID='272b7bb5-38e6-41b3-9da4-4cc278873fbf',
volUUID='d3011aef-3297-401c-88d7-65079e05dd4d', options=None)
Thread-867486::DEBUG::2013-11-26 14:58:52,534::lvm::415::OperationMutex::(_reloadlvs)
Operation 'lvm reload operation' got the operation mutex
Thread-867486::DEBUG::2013-11-26 14:58:52,539::lvm::311::Storage.Misc.excCmd::(cmd)
'/usr/bin/sudo -n /sbin/lvm lvs --config " devices { preferred_names =
[\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0
disable_after_error_count=3 filter = [
\'a|/dev/mapper/360014051fd69751de087d46f1da5aadb|/dev/mapper/360014056ce3d140de6a5d4fffd9218da|/dev/mapper/360014056db0fc0fdcda7d4a27da043d5|/dev/mapper/36001405917dfc0dd0809d41cfd86c9d4|/dev/mapper/3600508b1001cd6f84303d050b8fb5a80|\',
\'r|.*|\' ] } global { locking_type=1 prioritise_write_locks=1 wait_for_locks=1 }
backup { retain_min = 50 retain_days = 0 } " --noheadings --units b --nosuffix
--separator | -o uuid,name,vg_name,attr,size,seg_start_pe,devices,tags
8c8ad4f8-f187-410c-82a7-2beb79a51a30' (cwd None)
Thread-867486::DEBUG::2013-11-26 14:58:52,588::lvm::311::Storage.Misc.excCmd::(cmd)
SUCCESS: <err> = ''; <rc> = 0
Thread-867486::DEBUG::2013-11-26 14:58:52,623::lvm::448::OperationMutex::(_reloadlvs)
Operation 'lvm reload operation' released the operation mutex
Thread-867486::INFO::2013-11-26 14:58:52,623::logUtils::47::dispatcher::(wrapper) Run and
protect: getVolumeSize, Return response: {'truesize': '42949672960',
'apparentsize': '42949672960'}
Thread-867486::DEBUG::2013-11-26 14:58:52,624::task::1168::TaskManager.Task::(prepare)
Task=`e64eb271-e389-4057-81f7-1148059464d7`::finished: {'truesize':
'42949672960', 'apparentsize': '42949672960'}
Thread-867486::DEBUG::2013-11-26 14:58:52,624::task::579::TaskManager.Task::(_updateState)
Task=`e64eb271-e389-4057-81f7-1148059464d7`::moving from state preparing -> state
finished
Thread-867486::DEBUG::2013-11-26
14:58:52,624::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll
requests {} resources {}
Thread-867486::DEBUG::2013-11-26
14:58:52,625::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll
requests {}
Thread-867486::DEBUG::2013-11-26 14:58:52,625::task::974::TaskManager.Task::(_decref)
Task=`e64eb271-e389-4057-81f7-1148059464d7`::ref 0 aborting False
Thread-867486::INFO::2013-11-26 14:58:52,625::clientIF::325::vds::(prepareVolumePath)
prepared volume path:
Thread-867486::DEBUG::2013-11-26 14:58:52,626::task::579::TaskManager.Task::(_updateState)
Task=`e0d9071f-a343-400e-865d-81656dd8862b`::moving from state init -> state preparing
Thread-867486::INFO::2013-11-26 14:58:52,626::logUtils::44::dispatcher::(wrapper) Run and
protect: prepareImage(sdUUID='8c8ad4f8-f187-410c-82a7-2beb79a51a30',
spUUID='5849b030-626e-47cb-ad90-3ce782d831b3',
imgUUID='272b7bb5-38e6-41b3-9da4-4cc278873fbf',
volUUID='d3011aef-3297-401c-88d7-65079e05dd4d')
Thread-867486::DEBUG::2013-11-26
14:58:52,627::resourceManager::197::ResourceManager.Request::(__init__)
ResName=`Storage.8c8ad4f8-f187-410c-82a7-2beb79a51a30`ReqID=`664dc122-58c1-49d1-a03e-faa2182f42da`::Request
was made in '/usr/share/vdsm/storage/hsm.py' line '3240' at
'prepareImage'
Thread-867486::DEBUG::2013-11-26
14:58:52,627::resourceManager::541::ResourceManager::(registerResource) Trying to register
resource 'Storage.8c8ad4f8-f187-410c-82a7-2beb79a51a30' for lock type
'shared'
Thread-867486::DEBUG::2013-11-26
14:58:52,628::resourceManager::600::ResourceManager::(registerResource) Resource
'Storage.8c8ad4f8-f187-410c-82a7-2beb79a51a30' is free. Now locking as
'shared' (1 active user)
Thread-867486::DEBUG::2013-11-26
14:58:52,628::resourceManager::237::ResourceManager.Request::(grant)
ResName=`Storage.8c8ad4f8-f187-410c-82a7-2beb79a51a30`ReqID=`664dc122-58c1-49d1-a03e-faa2182f42da`::Granted
request
Thread-867486::DEBUG::2013-11-26
14:58:52,629::task::811::TaskManager.Task::(resourceAcquired)
Task=`e0d9071f-a343-400e-865d-81656dd8862b`::_resourcesAcquired:
Storage.8c8ad4f8-f187-410c-82a7-2beb79a51a30 (shared)
Thread-867486::DEBUG::2013-11-26 14:58:52,629::task::974::TaskManager.Task::(_decref)
Task=`e0d9071f-a343-400e-865d-81656dd8862b`::ref 1 aborting False
Thread-867486::DEBUG::2013-11-26
14:58:52,635::blockVolume::588::Storage.Misc.excCmd::(getMetadata) '/bin/dd
iflag=direct skip=23 bs=512 if=/dev/8c8ad4f8-f187-410c-82a7-2beb79a51a30/metadata
count=1' (cwd None)
Thread-867486::DEBUG::2013-11-26
14:58:52,644::blockVolume::588::Storage.Misc.excCmd::(getMetadata) SUCCESS: <err> =
'1+0 records in\n1+0 records out\n512 bytes (512 B) copied, 0.000281928 s, 1.8
MB/s\n'; <rc> = 0
Thread-867486::DEBUG::2013-11-26 14:58:52,644::misc::288::Storage.Misc::(validateDDBytes)
err: ['1+0 records in', '1+0 records out', '512 bytes (512 B) copied,
0.000281928 s, 1.8 MB/s'], size: 512
Thread-867486::INFO::2013-11-26 14:58:52,645::image::215::Storage.Image::(getChain)
sdUUID=8c8ad4f8-f187-410c-82a7-2beb79a51a30 imgUUID=272b7bb5-38e6-41b3-9da4-4cc278873fbf
chain=[<storage.blockVolume.BlockVolume object at 0x14f6ad0>]
Thread-867486::DEBUG::2013-11-26 14:58:52,646::lvm::311::Storage.Misc.excCmd::(cmd)
'/usr/bin/sudo -n /sbin/lvm lvchange --config " devices { preferred_names =
[\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0
disable_after_error_count=3 filter = [
\'a|/dev/mapper/360014051fd69751de087d46f1da5aadb|/dev/mapper/360014056ce3d140de6a5d4fffd9218da|/dev/mapper/360014056db0fc0fdcda7d4a27da043d5|/dev/mapper/36001405917dfc0dd0809d41cfd86c9d4|/dev/mapper/3600508b1001cd6f84303d050b8fb5a80|\',
\'r|.*|\' ] } global { locking_type=1 prioritise_write_locks=1 wait_for_locks=1 }
backup { retain_min = 50 retain_days = 0 } " --autobackup n --available y
8c8ad4f8-f187-410c-82a7-2beb79a51a30/d3011aef-3297-401c-88d7-65079e05dd4d' (cwd None)
Thread-867486::DEBUG::2013-11-26 14:58:52,942::lvm::311::Storage.Misc.excCmd::(cmd)
SUCCESS: <err> = ''; <rc> = 0
Thread-867486::DEBUG::2013-11-26 14:58:52,943::lvm::499::OperationMutex::(_invalidatelvs)
Operation 'lvm invalidate operation' got the operation mutex
Thread-867486::DEBUG::2013-11-26 14:58:52,943::lvm::511::OperationMutex::(_invalidatelvs)
Operation 'lvm invalidate operation' released the operation mutex
Thread-867486::DEBUG::2013-11-26 14:58:52,943::lvm::415::OperationMutex::(_reloadlvs)
Operation 'lvm reload operation' got the operation mutex
Thread-867486::DEBUG::2013-11-26 14:58:52,944::lvm::311::Storage.Misc.excCmd::(cmd)
'/usr/bin/sudo -n /sbin/lvm lvs --config " devices { preferred_names =
[\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0
disable_after_error_count=3 filter = [
\'a|/dev/mapper/360014051fd69751de087d46f1da5aadb|/dev/mapper/360014056ce3d140de6a5d4fffd9218da|/dev/mapper/360014056db0fc0fdcda7d4a27da043d5|/dev/mapper/36001405917dfc0dd0809d41cfd86c9d4|/dev/mapper/3600508b1001cd6f84303d050b8fb5a80|\',
\'r|.*|\' ] } global { locking_type=1 prioritise_write_locks=1 wait_for_locks=1 }
backup { retain_min = 50 retain_days = 0 } " --noheadings --units b --nosuffix
--separator | -o uuid,name,vg_name,attr,size,seg_start_pe,devices,tags
8c8ad4f8-f187-410c-82a7-2beb79a51a30' (cwd None)
Thread-867486::DEBUG::2013-11-26 14:58:53,242::lvm::311::Storage.Misc.excCmd::(cmd)
SUCCESS: <err> = ''; <rc> = 0
Thread-867486::DEBUG::2013-11-26 14:58:53,277::lvm::448::OperationMutex::(_reloadlvs)
Operation 'lvm reload operation' released the operation mutex
Thread-867486::DEBUG::2013-11-26
14:58:53,283::blockVolume::588::Storage.Misc.excCmd::(getMetadata) '/bin/dd
iflag=direct skip=23 bs=512 if=/dev/8c8ad4f8-f187-410c-82a7-2beb79a51a30/metadata
count=1' (cwd None)
Thread-867486::DEBUG::2013-11-26
14:58:53,292::blockVolume::588::Storage.Misc.excCmd::(getMetadata) SUCCESS: <err> =
'1+0 records in\n1+0 records out\n512 bytes (512 B) copied, 0.000298328 s, 1.7
MB/s\n'; <rc> = 0
Thread-867486::DEBUG::2013-11-26 14:58:53,292::misc::288::Storage.Misc::(validateDDBytes)
err: ['1+0 records in', '1+0 records out', '512 bytes (512 B) copied,
0.000298328 s, 1.7 MB/s'], size: 512
Thread-867486::INFO::2013-11-26 14:58:53,293::logUtils::47::dispatcher::(wrapper) Run and
protect: prepareImage, Return response: {'info': {'path':
'/rhev/data-center/5849b030-626e-47cb-ad90-3ce782d831b3/8c8ad4f8-f187-410c-82a7-2beb79a51a30/images/272b7bb5-38e6-41b3-9da4-4cc278873fbf/d3011aef-3297-401c-88d7-65079e05dd4d',
'volType': 'path'}, 'path':
'/rhev/data-center/5849b030-626e-47cb-ad90-3ce782d831b3/8c8ad4f8-f187-410c-82a7-2beb79a51a30/images/272b7bb5-38e6-41b3-9da4-4cc278873fbf/d3011aef-3297-401c-88d7-65079e05dd4d',
'chain': [{'path':
'/rhev/data-center/5849b030-626e-47cb-ad90-3ce782d831b3/8c8ad4f8-f187-410c-82a7-2beb79a51a30/images/272b7bb5-38e6-41b3-9da4-4cc278873fbf/d3011aef-3297-401c-88d7-65079e05dd4d',
'domainID': '8c8ad4f8-f187-410c-82a7-2beb79a51a30', 'vmVolInfo':
{'path':
'/rhev/data-center/5849b030-626e-47cb-ad90-3ce782d831b3/8c8ad4f8-f187-410c-82a7-2beb79a51a30/images/272b7bb5-38e6-41b3-9da4-4cc278873fbf/d3011aef-3297-401c-88d7-65079e05dd4d',
'volType': 'path'}, 'volumeID':
'd3011aef-3297-401c-88d7-65079e05dd4d', 'imageID':
'272b7bb5-38e6-41b3-9da4-4cc278873fbf'}]}
Thread-867486::DEBUG::2013-11-26 14:58:53,293::task::1168::TaskManager.Task::(prepare)
Task=`e0d9071f-a343-400e-865d-81656dd8862b`::finished: {'info': {'path':
'/rhev/data-center/5849b030-626e-47cb-ad90-3ce782d831b3/8c8ad4f8-f187-410c-82a7-2beb79a51a30/images/272b7bb5-38e6-41b3-9da4-4cc278873fbf/d3011aef-3297-401c-88d7-65079e05dd4d',
'volType': 'path'}, 'path':
'/rhev/data-center/5849b030-626e-47cb-ad90-3ce782d831b3/8c8ad4f8-f187-410c-82a7-2beb79a51a30/images/272b7bb5-38e6-41b3-9da4-4cc278873fbf/d3011aef-3297-401c-88d7-65079e05dd4d',
'chain': [{'path':
'/rhev/data-center/5849b030-626e-47cb-ad90-3ce782d831b3/8c8ad4f8-f187-410c-82a7-2beb79a51a30/images/272b7bb5-38e6-41b3-9da4-4cc278873fbf/d3011aef-3297-401c-88d7-65079e05dd4d',
'domainID': '8c8ad4f8-f187-410c-82a7-2beb79a51a30', 'vmVolInfo':
{'path':
'/rhev/data-center/5849b030-626e-47cb-ad90-3ce782d831b3/8c8ad4f8-f187-410c-82a7-2beb79a51a30/images/272b7bb5-38e6-41b3-9da4-4cc278873fbf/d3011aef-3297-401c-88d7-65079e05dd4d',
'volType': 'path'}, 'volumeID':
'd3011aef-3297-401c-88d7-65079e05dd4d', 'imageID':
'272b7bb5-38e6-41b3-9da4-4cc278873fbf'}]}
Thread-867486::DEBUG::2013-11-26 14:58:53,293::task::579::TaskManager.Task::(_updateState)
Task=`e0d9071f-a343-400e-865d-81656dd8862b`::moving from state preparing -> state
finished
Thread-867486::DEBUG::2013-11-26
14:58:53,294::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll
requests {} resources {'Storage.8c8ad4f8-f187-410c-82a7-2beb79a51a30': <
ResourceRef 'Storage.8c8ad4f8-f187-410c-82a7-2beb79a51a30', isValid:
'True' obj: 'None'>}
Thread-867486::DEBUG::2013-11-26
14:58:53,294::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll
requests {}
Thread-867486::DEBUG::2013-11-26
14:58:53,294::resourceManager::615::ResourceManager::(releaseResource) Trying to release
resource 'Storage.8c8ad4f8-f187-410c-82a7-2beb79a51a30'
Thread-867486::DEBUG::2013-11-26
14:58:53,295::resourceManager::634::ResourceManager::(releaseResource) Released resource
'Storage.8c8ad4f8-f187-410c-82a7-2beb79a51a30' (0 active users)
Thread-867486::DEBUG::2013-11-26
14:58:53,295::resourceManager::640::ResourceManager::(releaseResource) Resource
'Storage.8c8ad4f8-f187-410c-82a7-2beb79a51a30' is free, finding out if anyone is
waiting for it.
Thread-867486::DEBUG::2013-11-26
14:58:53,295::resourceManager::648::ResourceManager::(releaseResource) No one is waiting
for resource 'Storage.8c8ad4f8-f187-410c-82a7-2beb79a51a30', Clearing records.
Thread-867486::DEBUG::2013-11-26 14:58:53,296::task::974::TaskManager.Task::(_decref)
Task=`e0d9071f-a343-400e-865d-81656dd8862b`::ref 0 aborting False
Thread-867486::INFO::2013-11-26 14:58:53,296::clientIF::325::vds::(prepareVolumePath)
prepared volume path:
/rhev/data-center/5849b030-626e-47cb-ad90-3ce782d831b3/8c8ad4f8-f187-410c-82a7-2beb79a51a30/images/272b7bb5-38e6-41b3-9da4-4cc278873fbf/d3011aef-3297-401c-88d7-65079e05dd4d
Thread-867486::DEBUG::2013-11-26 14:58:53,318::utils::486::root::(execCmd)
'/usr/libexec/vdsm/hooks/before_vm_start/50_smbios' (cwd None)
Thread-867486::DEBUG::2013-11-26 14:58:53,400::utils::505::root::(execCmd) SUCCESS:
<err> = ''; <rc> = 0
Thread-867486::INFO::2013-11-26 14:58:53,401::hooks::88::root::(_runHooksDir)
Thread-867486::DEBUG::2013-11-26 14:58:53,401::vm::2872::vm.Vm::(_run)
vmId=`8798d0da-a82c-4bcf-b41a-7e3fe1c613ef`::<?xml version="1.0"
encoding="utf-8"?>
<domain type="kvm">
<name>vm01</name>
<uuid>8798d0da-a82c-4bcf-b41a-7e3fe1c613ef</uuid>
<memory>1048576</memory>
<currentMemory>1048576</currentMemory>
<vcpu>1</vcpu>
<memtune>
<min_guarantee>524288</min_guarantee>
</memtune>
<devices>
<channel type="unix">
<target name="com.redhat.rhevm.vdsm" type="virtio"/>
<source mode="bind"
path="/var/lib/libvirt/qemu/channels/8798d0da-a82c-4bcf-b41a-7e3fe1c613ef.com.redhat.rhevm.vdsm"/>
</channel>
<channel type="unix">
<target name="org.qemu.guest_agent.0" type="virtio"/>
<source mode="bind"
path="/var/lib/libvirt/qemu/channels/8798d0da-a82c-4bcf-b41a-7e3fe1c613ef.org.qemu.guest_agent.0"/>
</channel>
<input bus="usb" type="tablet"/>
<graphics autoport="yes" keymap="de" listen="0"
passwd="*****" passwdValidTo="1970-01-01T00:00:01" port="-1"
type="vnc"/>
<video>
<address bus="0x00" domain="0x0000" function="0x0"
slot="0x02" type="pci"/>
<model heads="1" type="cirrus" vram="65536"/>
</video>
<interface type="bridge">
<address bus="0x00" domain="0x0000" function="0x0"
slot="0x03" type="pci"/>
<mac address="52:54:00:6d:ce:c8"/>
<model type="virtio"/>
<source bridge="VM"/>
<filterref filter="vdsm-no-mac-spoofing"/>
<link state="up"/>
</interface>
<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/>
</disk>
<disk device="disk" snapshot="no" type="block">
<address bus="0x00" domain="0x0000" function="0x0"
slot="0x05" type="pci"/>
<source
dev="/rhev/data-center/5849b030-626e-47cb-ad90-3ce782d831b3/8c8ad4f8-f187-410c-82a7-2beb79a51a30/images/272b7bb5-38e6-41b3-9da4-4cc278873fbf/d3011aef-3297-401c-88d7-65079e05dd4d"/>
<target bus="virtio" dev="vda"/>
<serial>272b7bb5-38e6-41b3-9da4-4cc278873fbf</serial>
<boot order="1"/>
<driver cache="none" error_policy="stop" io="native"
name="qemu" type="raw"/>
</disk>
<memballoon model="none"/>
</devices>
<os>
<type arch="x86_64" machine="rhel6.4.0">hvm</type>
<smbios mode="sysinfo"/>
</os>
<sysinfo type="smbios">
<system>
<entry name="manufacturer">oVirt</entry>
<entry name="product">oVirt Node</entry>
<entry name="version">6-4.el6.centos.10</entry>
<entry name="serial">32393735-3933-5A43-4A32-34333046564B</entry>
<entry name="uuid">8798d0da-a82c-4bcf-b41a-7e3fe1c613ef</entry>
</system>
</sysinfo>
<clock adjustment="1" offset="variable">
<timer name="rtc" tickpolicy="catchup"/>
</clock>
<features>
<acpi/>
</features>
<cpu match="exact">
<model>Nehalem</model>
<topology cores="1" sockets="1" threads="1"/>
</cpu>
</domain>
Thread-166407::DEBUG::2013-11-26
14:58:53,588::blockSD::594::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct
if=/dev/8c8ad4f8-f187-410c-82a7-2beb79a51a30/metadata bs=4096 count=1' (cwd None)
Thread-166407::DEBUG::2013-11-26
14:58:53,599::blockSD::594::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> =
'1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000345562 s, 11.9
MB/s\n'; <rc> = 0
Thread-24::DEBUG::2013-11-26
14:58:53,791::fileSD::238::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct
if=/rhev/data-center/mnt/engine.privat.com:_export_VMs/48055e27-f1ca-466a-8a2c-e191c34f0226/dom_md/metadata
bs=4096 count=1' (cwd None)
Thread-24::DEBUG::2013-11-26
14:58:53,801::fileSD::238::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> =
'0+1 records in\n0+1 records out\n349 bytes (349 B) copied, 0.000683955 s, 510
kB/s\n'; <rc> = 0
libvirtEventLoop::DEBUG::2013-11-26
14:58:54,094::vm::4724::vm.Vm::(_onLibvirtLifecycleEvent)
vmId=`8798d0da-a82c-4bcf-b41a-7e3fe1c613ef`::event Started detail 0 opaque None
Thread-867486::DEBUG::2013-11-26 14:58:54,248::sampling::285::vm.Vm::(start)
vmId=`8798d0da-a82c-4bcf-b41a-7e3fe1c613ef`::Start statistics collection
Thread-867488::DEBUG::2013-11-26 14:58:54,249::sampling::314::vm.Vm::(run)
vmId=`8798d0da-a82c-4bcf-b41a-7e3fe1c613ef`::Stats thread started
Thread-867486::DEBUG::2013-11-26 14:58:54,251::vmChannels::194::vds::(register) Add fileno
51 to listener's channels.
Thread-867488::DEBUG::2013-11-26 14:58:54,253::task::579::TaskManager.Task::(_updateState)
Task=`c5c6d816-7de8-4ab5-a5fa-a3fba225d797`::moving from state init -> state preparing
Thread-867488::INFO::2013-11-26 14:58:54,253::logUtils::44::dispatcher::(wrapper) Run and
protect: getVolumeSize(sdUUID='8c8ad4f8-f187-410c-82a7-2beb79a51a30',
spUUID='5849b030-626e-47cb-ad90-3ce782d831b3',
imgUUID='272b7bb5-38e6-41b3-9da4-4cc278873fbf',
volUUID='d3011aef-3297-401c-88d7-65079e05dd4d', options=None)
Thread-867486::WARNING::2013-11-26 14:58:54,253::vm::3326::vm.Vm::(_readPauseCode)
vmId=`8798d0da-a82c-4bcf-b41a-7e3fe1c613ef`::_readPauseCode unsupported by libvirt vm
Thread-867488::INFO::2013-11-26 14:58:54,255::logUtils::47::dispatcher::(wrapper) Run and
protect: getVolumeSize, Return response: {'truesize': '42949672960',
'apparentsize': '42949672960'}
Thread-867488::DEBUG::2013-11-26 14:58:54,256::task::1168::TaskManager.Task::(prepare)
Task=`c5c6d816-7de8-4ab5-a5fa-a3fba225d797`::finished: {'truesize':
'42949672960', 'apparentsize': '42949672960'}
Thread-867488::DEBUG::2013-11-26 14:58:54,256::task::579::TaskManager.Task::(_updateState)
Task=`c5c6d816-7de8-4ab5-a5fa-a3fba225d797`::moving from state preparing -> state
finished
Thread-867488::DEBUG::2013-11-26
14:58:54,256::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll
requests {} resources {}
Thread-867488::DEBUG::2013-11-26
14:58:54,257::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll
requests {}
Thread-867488::DEBUG::2013-11-26 14:58:54,257::task::974::TaskManager.Task::(_decref)
Task=`c5c6d816-7de8-4ab5-a5fa-a3fba225d797`::ref 0 aborting False
Thread-867486::DEBUG::2013-11-26 14:58:54,263::vm::2036::vm.Vm::(_startUnderlyingVm)
vmId=`8798d0da-a82c-4bcf-b41a-7e3fe1c613ef`::_ongoingCreations released
VM Channels Listener::DEBUG::2013-11-26
14:58:54,694::vmChannels::102::vds::(_do_add_channels) fileno 51 was added to unconnected
channels.
VM Channels Listener::DEBUG::2013-11-26
14:58:54,694::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 51.
VM Channels Listener::DEBUG::2013-11-26 14:58:54,695::guestIF::147::vm.Vm::(_connect)
vmId=`8798d0da-a82c-4bcf-b41a-7e3fe1c613ef`::Attempting connection to
/var/lib/libvirt/qemu/channels/8798d0da-a82c-4bcf-b41a-7e3fe1c613ef.com.redhat.rhevm.vdsm
VM Channels Listener::DEBUG::2013-11-26 14:58:54,695::guestIF::150::vm.Vm::(_connect)
vmId=`8798d0da-a82c-4bcf-b41a-7e3fe1c613ef`::Connected to
/var/lib/libvirt/qemu/channels/8798d0da-a82c-4bcf-b41a-7e3fe1c613ef.com.redhat.rhevm.vdsm
VM Channels Listener::DEBUG::2013-11-26
14:58:54,695::vmChannels::144::vds::(_handle_unconnected) Connecting to fileno 51
succeeded.
Thread-867490::DEBUG::2013-11-26 14:58:55,170::BindingXMLRPC::979::vds::(wrapper) client
[192.168.1.29]::call vmGetStats with ('8798d0da-a82c-4bcf-b41a-7e3fe1c613ef',) {}
Thread-867490::DEBUG::2013-11-26 14:58:55,170::vm::579::vm.Vm::(_getCpuStats)
vmId=`8798d0da-a82c-4bcf-b41a-7e3fe1c613ef`::CPU stats not available: 'NoneType'
object is unsubscriptable
Thread-867490::DEBUG::2013-11-26 14:58:55,170::vm::613::vm.Vm::(_getNetworkStats)
vmId=`8798d0da-a82c-4bcf-b41a-7e3fe1c613ef`::Network stats not available
--========GMXBoundary242171385563631782200
Content-Type: text/html; charset="utf-8"
Content-Transfer-Encoding: quoted-printable
<span style=3D'font-family:Verdana'><span
style=3D'font-size:12px'>Hello,<b=
r /><br />I'm running in troubles.....<br />After migrating the storage
of =
an powered off VM to a different iSCSI storage, my CentOS 4 VM does not sta=
rt any more (well, it's not the reality, but for the system the VM stays in=
Wait for launch for hours). In reality, the VM starts on the node.<br /><b=
r />Any hints?<br /><br />My Config:<br />CentOS 6.4<br />oVirt
3.3.1-2<br =
/>VDSM 4.12.1-4<br /><br />engine.log<br /><br />2013-11-26
14:58:50,171 IN=
FO [org.ovirt.engine.core.bll.AsyncTaskManager] (DefaultQuartzSchedul=
er_Worker-46) Setting new tasks map. The map contains now 0 tasks<br />2013=
-11-26 14:58:50,172 INFO [org.ovirt.engine.core.bll.AsyncTaskManager]=
(DefaultQuartzScheduler_Worker-46) Cleared all tasks of pool 5849b030-626e=
-47cb-ad90-3ce782d831b3.<br />2013-11-26 14:58:52,106 INFO [org.ovirt=
.engine.core.bll.RunVmCommand] (ajp--127.0.0.1-8702-2) [574ec4d2] Lock Acqu=
ired to object EngineLock [exclusiveLocks=3D key: 8798d0da-a82c-4bcf-b41a-7=
e3fe1c613ef value: VM<br />, sharedLocks=3D ]<br />2013-11-26 14:58:52,124 =
INFO [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand]=
(ajp--127.0.0.1-8702-2) [574ec4d2] START, IsVmDuringInitiatingVDSCommand( =
vmId =3D 8798d0da-a82c-4bcf-b41a-7e3fe1c613ef), log id: 13e7aadf<br />2013-=
11-26 14:58:52,125 INFO [org.ovirt.engine.core.vdsbroker.IsVmDuringIn=
itiatingVDSCommand] (ajp--127.0.0.1-8702-2) [574ec4d2] FINISH, IsVmDuringIn=
itiatingVDSCommand, return: false, log id: 13e7aadf<br />2013-11-26 14:58:5=
2,251 INFO [org.ovirt.engine.core.bll.RunVmCommand] (pool-6-thread-50=
) [574ec4d2] Running command: RunVmCommand internal: false. Entities affect=
ed : ID: 8798d0da-a82c-4bcf-b41a-7e3fe1c613ef Type: VM<br />2013-11-2=
6 14:58:52,406 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.IsoPre=
fixVDSCommand] (pool-6-thread-50) [574ec4d2] START, IsoPrefixVDSCommand(Hos=
tName =3D HOST01, HostId =3D b34d1e33-bdda-4ba8-9c23-0d136f372ad8, storageP=
oolId=3D5849b030-626e-47cb-ad90-3ce782d831b3), log id: 1a6a3b22<br />2013-1=
1-26 14:58:52,408 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.Iso=
PrefixVDSCommand] (pool-6-thread-50) [574ec4d2] FINISH, IsoPrefixVDSCommand=
, return: /rhev/data-center/mnt/engine.private.com:_var_lib_exports_iso/53a=
22027-fd2d-451b-8cd7-0e604fb8e460/images/11111111-1111-1111-1111-1111111111=
11, log id: 1a6a3b22<br />2013-11-26 14:58:52,441 INFO [org.ovirt.eng=
ine.core.vdsbroker.CreateVmVDSCommand] (pool-6-thread-50) [574ec4d2] START,=
CreateVmVDSCommand(HostName =3D HOST01, HostId =3D b34d1e33-bdda-4ba8-9c23=
-0d136f372ad8, vmId=3D8798d0da-a82c-4bcf-b41a-7e3fe1c613ef, vm=3DVM [vm01])=
, log id: 2da012df<br />2013-11-26 14:58:52,476 INFO [org.ovirt.engin=
e.core.vdsbroker.vdsbroker.CreateVDSCommand] (pool-6-thread-50) [574ec4d2] =
START, CreateVDSCommand(HostName =3D HOST01, HostId =3D b34d1e33-bdda-4ba8-=
9c23-0d136f372ad8, vmId=3D8798d0da-a82c-4bcf-b41a-7e3fe1c613ef, vm=3DVM [vm=
01]), log id: 727a7bf7<br />2013-11-26 14:58:52,539 INFO [org.ovirt.e=
ngine.core.vdsbroker.vdsbroker.CreateVDSCommand] (pool-6-thread-50) [574ec4=
d2] org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand spiceSslCiph=
erSuite=3DDEFAULT,memSize=3D1024,kvmEnable=3Dtrue,smp=3D1,vmType=3Dkvm,emul=
atedMachine=3Drhel6.4.0,keyboardLayout=3Dde,memGuaranteedSize=3D512,pitRein=
jection=3Dfalse,nice=3D0,display=3Dvnc,smartcardEnable=3Dfalse,tabletEnable=
=3Dtrue,smpCoresPerSocket=3D1,spiceSecureChannels=3Dsmain,sinputs,scursor,s=
playback,srecord,sdisplay,susbredir,ssmartcard,timeOffset=3D1,transparentHu=
gePages=3Dtrue,vmId=3D8798d0da-a82c-4bcf-b41a-7e3fe1c613ef,devices=3D[Ljava=
.util.HashMap;@1030ba06,acpiEnable=3Dtrue,vmName=3Dvm01,cpuType=3DNehalem,c=
ustom=3D{device_99b583e9-9030-40af-bb41-55d62a4a6b6adevice_5b94ca77-fab8-41=
b4-b286-311dee724813=3DVmDevice {vmId=3D8798d0da-a82c-4bcf-b41a-7e3fe1c613e=
f, deviceId=3D5b94ca77-fab8-41b4-b286-311dee724813, device=3Dunix, type=3DC=
HANNEL, bootOrder=3D0, specParams=3D{}, address=3D{port=3D2, bus=3D0, contr=
oller=3D0, type=3Dvirtio-serial}, managed=3Dfalse, plugged=3Dtrue, readOnly=
=3Dfalse, deviceAlias=3Dchannel1, customProperties=3D{}}, device_99b583e9-9=
030-40af-bb41-55d62a4a6b6a=3DVmDevice {vmId=3D8798d0da-a82c-4bcf-b41a-7e3fe=
1c613ef, deviceId=3D99b583e9-9030-40af-bb41-55d62a4a6b6a, device=3Dunix, ty=
pe=3DCHANNEL, bootOrder=3D0, specParams=3D{}, address=3D{port=3D1, bus=3D0,=
controller=3D0, type=3Dvirtio-serial}, managed=3Dfalse, plugged=3Dtrue, re=
adOnly=3Dfalse, deviceAlias=3Dchannel0, customProperties=3D{}}, device_99b5=
83e9-9030-40af-bb41-55d62a4a6b6adevice_5b94ca77-fab8-41b4-b286-311dee724813=
device_c3d8dcbf-d977-4d4d-8240-35b973ee00b9device_839371b0-1967-4435-910e-0=
d8e1c980850=3DVmDevice {vmId=3D8798d0da-a82c-4bcf-b41a-7e3fe1c613ef, device=
Id=3D839371b0-1967-4435-910e-0d8e1c980850, device=3Dide, type=3DCONTROLLER,=
bootOrder=3D0, specParams=3D{}, address=3D{bus=3D0x00, domain=3D0x0000, ty=
pe=3Dpci, slot=3D0x01, function=3D0x1}, managed=3Dfalse, plugged=3Dtrue, re=
adOnly=3Dfalse, deviceAlias=3Dide0, customProperties=3D{}}, device_99b583e9=
-9030-40af-bb41-55d62a4a6b6adevice_5b94ca77-fab8-41b4-b286-311dee724813devi=
ce_c3d8dcbf-d977-4d4d-8240-35b973ee00b9=3DVmDevice {vmId=3D8798d0da-a82c-4b=
cf-b41a-7e3fe1c613ef, deviceId=3Dc3d8dcbf-d977-4d4d-8240-35b973ee00b9, devi=
ce=3Dscsi, type=3DCONTROLLER, bootOrder=3D0, specParams=3D{}, address=3D{bu=
s=3D0x00, domain=3D0x0000, type=3Dpci, slot=3D0x04, function=3D0x0}, manage=
d=3Dfalse, plugged=3Dtrue, readOnly=3Dfalse, deviceAlias=3Dscsi0, customPro=
perties=3D{}}, device_99b583e9-9030-40af-bb41-55d62a4a6b6adevice_5b94ca77-f=
ab8-41b4-b286-311dee724813device_c3d8dcbf-d977-4d4d-8240-35b973ee00b9device=
_839371b0-1967-4435-910e-0d8e1c980850device_920282ca-79c2-4abf-b1f2-7425f16=
f7820=3DVmDevice {vmId=3D8798d0da-a82c-4bcf-b41a-7e3fe1c613ef, deviceId=3D9=
20282ca-79c2-4abf-b1f2-7425f16f7820, device=3Dvirtio-serial, type=3DCONTROL=
LER, bootOrder=3D0, specParams=3D{}, address=3D{bus=3D0x00, domain=3D0x0000=
, type=3Dpci, slot=3D0x06, function=3D0x0}, managed=3Dfalse, plugged=3Dtrue=
, readOnly=3Dfalse, deviceAlias=3Dvirtio-serial0, customProperties=3D{}}}<b=
r />2013-11-26 14:58:52,552 INFO [org.ovirt.engine.core.vdsbroker.vds=
broker.CreateVDSCommand] (pool-6-thread-50) [574ec4d2] FINISH, CreateVDSCom=
mand, log id: 727a7bf7<br />2013-11-26 14:58:52,567 INFO [org.ovirt.e=
ngine.core.vdsbroker.CreateVmVDSCommand] (pool-6-thread-50) [574ec4d2] FINI=
SH, CreateVmVDSCommand, return: WaitForLaunch, log id: 2da012df<br />2013-1=
1-26 14:58:52,568 INFO [org.ovirt.engine.core.bll.RunVmCommand] (pool=
-6-thread-50) [574ec4d2] Lock freed to object EngineLock [exclusiveLocks=3D=
key: 8798d0da-a82c-4bcf-b41a-7e3fe1c613ef value: VM<br />, sharedLocks=3D =
]<br />2013-11-26 14:58:52,576 INFO [org.ovirt.engine.core.dal.dbbrok=
er.auditloghandling.AuditLogDirector] (pool-6-thread-50) [574ec4d2] Correla=
tion ID: 574ec4d2, Job ID: d3d270e1-607b-4599-983a-1ef884e81a43, Call Stack=
: null, Custom Event ID: -1, Message: VM vm01 was started by User01 (Host: =
HOST01).<br />2013-11-26 14:58:55,177 WARN [org.ovirt.engine.core.vds=
broker.VdsManager] (DefaultQuartzScheduler_Worker-33) Failed to refresh VDS=
, vds =3D b34d1e33-bdda-4ba8-9c23-0d136f372ad8 : HOST01, error =3D java.la=
ng.NullPointerException, continuing.: java.lang.NullPointerException<br />&=
nbsp; at
org.ovirt.engine.core.vdsbroke=
r.VdsUpdateRunTimeInfo.proceedBalloonCheck(VdsUpdateRunTimeInfo.java:1312) =
[vdsbroker.jar:]<br
/> at org.ovi=
rt.engine.core.vdsbroker.VdsUpdateRunTimeInfo.refreshVmStats(VdsUpdateRunTi=
meInfo.java:926) [vdsbroker.jar:]<br
/> =
at org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo.refreshVdsRu=
nTimeInfo(VdsUpdateRunTimeInfo.java:502) [vdsbroker.jar:]<br
/> =
at
org.ovirt.engine.core.vdsbroker.VdsUpdate=
RunTimeInfo.Refresh(VdsUpdateRunTimeInfo.java:343) [vdsbroker.jar:]<br />&n=
bsp; at
org.ovirt.engine.core.vdsbroker=
.VdsManager.OnTimer(VdsManager.java:237) [vdsbroker.jar:]<br
/> =
at
sun.reflect.GeneratedMethodAccessor9.invo=
ke(Unknown Source) [:1.7.0_45]<br
/> &nb=
sp; at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAcce=
ssorImpl.java:43) [rt.jar:1.7.0_45]<br
/> &nbs=
p; at java.lang.reflect.Method.invoke(Method.java:606) [rt.jar:1.7.0_=
45]<br /> at
org.ovirt.engine.cor=
e.utils.timer.JobWrapper.execute(JobWrapper.java:60) [scheduler.jar:]<br />=
at
org.quartz.core.JobRunShell.r=
un(JobRunShell.java:213) [quartz.jar:]<br
/> &=
nbsp; at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThr=
eadPool.java:557) [quartz.jar:]<br /><br />vdsm.log<br
/>Thread-867485::DEB=
UG::2013-11-26 14:58:52,504::BindingXMLRPC::979::vds::(wrapper) client [192=
.168.1.29]::call vmCreate with ({'acpiEnable': 'true',
'emulatedMachine': '=
rhel6.4.0', 'tabletEnable': 'true', 'vmId':
'8798d0da-a82c-4bcf-b41a-7e3fe1=
c613ef', 'memGuaranteedSize': 512, 'spiceSslCipherSuite':
'DEFAULT', 'timeO=
ffset': '1', 'cpuType': 'Nehalem', 'custom':
{'device_99b583e9-9030-40af-bb=
41-55d62a4a6b6adevice_5b94ca77-fab8-41b4-b286-311dee724813device_c3d8dcbf-d=
977-4d4d-8240-35b973ee00b9': 'VmDevice {vmId=3D8798d0da-a82c-4bcf-b41a-7e3f=
e1c613ef, deviceId=3Dc3d8dcbf-d977-4d4d-8240-35b973ee00b9, device=3Dscsi, t=
ype=3DCONTROLLER, bootOrder=3D0, specParams=3D{}, address=3D{bus=3D0x00, do=
main=3D0x0000, type=3Dpci, slot=3D0x04, function=3D0x0}, managed=3Dfalse, p=
lugged=3Dtrue, readOnly=3Dfalse, deviceAlias=3Dscsi0, customProperties=3D{}=
}', 'device_99b583e9-9030-40af-bb41-55d62a4a6b6a': 'VmDevice
{vmId=3D8798d0=
da-a82c-4bcf-b41a-7e3fe1c613ef, deviceId=3D99b583e9-9030-40af-bb41-55d62a4a=
6b6a, device=3Dunix, type=3DCHANNEL, bootOrder=3D0, specParams=3D{}, addres=
s=3D{port=3D1, bus=3D0, controller=3D0, type=3Dvirtio-serial}, managed=3Dfa=
lse, plugged=3Dtrue, readOnly=3Dfalse, deviceAlias=3Dchannel0, customProper=
ties=3D{}}', 'device_99b583e9-9030-40af-bb41-55d62a4a6b6adevice_5b94ca77-fa=
b8-41b4-b286-311dee724813device_c3d8dcbf-d977-4d4d-8240-35b973ee00b9device_=
839371b0-1967-4435-910e-0d8e1c980850device_920282ca-79c2-4abf-b1f2-7425f16f=
7820': 'VmDevice {vmId=3D8798d0da-a82c-4bcf-b41a-7e3fe1c613ef, deviceId=3D9=
20282ca-79c2-4abf-b1f2-7425f16f7820, device=3Dvirtio-serial, type=3DCONTROL=
LER, bootOrder=3D0, specParams=3D{}, address=3D{bus=3D0x00, domain=3D0x0000=
, type=3Dpci, slot=3D0x06, function=3D0x0}, managed=3Dfalse, plugged=3Dtrue=
, readOnly=3Dfalse, deviceAlias=3Dvirtio-serial0, customProperties=3D{}}', =
'device_99b583e9-9030-40af-bb41-55d62a4a6b6adevice_5b94ca77-fab8-41b4-b286-=
311dee724813device_c3d8dcbf-d977-4d4d-8240-35b973ee00b9device_839371b0-1967=
-4435-910e-0d8e1c980850': 'VmDevice {vmId=3D8798d0da-a82c-4bcf-b41a-7e3fe1c=
613ef, deviceId=3D839371b0-1967-4435-910e-0d8e1c980850, device=3Dide, type=
=3DCONTROLLER, bootOrder=3D0, specParams=3D{}, address=3D{bus=3D0x00, domai=
n=3D0x0000, type=3Dpci, slot=3D0x01, function=3D0x1}, managed=3Dfalse, plug=
ged=3Dtrue, readOnly=3Dfalse, deviceAlias=3Dide0, customProperties=3D{}}', =
'device_99b583e9-9030-40af-bb41-55d62a4a6b6adevice_5b94ca77-fab8-41b4-b286-=
311dee724813': 'VmDevice {vmId=3D8798d0da-a82c-4bcf-b41a-7e3fe1c613ef, devi=
ceId=3D5b94ca77-fab8-41b4-b286-311dee724813, device=3Dunix, type=3DCHANNEL,=
bootOrder=3D0, specParams=3D{}, address=3D{port=3D2, bus=3D0, controller=
=3D0, type=3Dvirtio-serial}, managed=3Dfalse, plugged=3Dtrue, readOnly=3Dfa=
lse, deviceAlias=3Dchannel1, customProperties=3D{}}'}, 'smp': '1',
'vmType'=
: 'kvm', 'memSize': 1024, 'smpCoresPerSocket': '1',
'vmName':<br />'vm01', =
'nice': '0', 'smartcardEnable': 'false',
'keyboardLayout': 'de', 'kvmEnable=
': 'true', 'pitReinjection': 'false',
'transparentHugePages': 'true', 'devi=
ces': [{'device': 'cirrus', 'specParams': {'vram':
'65536'}, 'type': 'video=
', 'deviceId': 'bf71f555-dc86-417b-9649-b06083b863b8',
'address': {'bus': '=
0x00', ' slot': '0x02', ' domain': '0x0000', '
type': 'pci', ' function': '=
0x0'}}, {'index': '2', 'iface': 'ide',
'address': {' controller': '0', ' ta=
rget': '0', 'unit': '0', ' bus': '1', '
type': 'drive'}, 'specParams': {'pa=
th': ''}, 'readonly': 'true', 'deviceId':
'865f42a1-f64a-49cd-a706-76bc1bea=
8517', 'path': '', 'device': 'cdrom',
'shared': 'false', 'type': 'disk'}, {=
'index': 0, 'iface': 'virtio', 'format': 'raw',
'bootOrder': '1', 'poolID':=
'5849b030-626e-47cb-ad90-3ce782d831b3', 'volumeID':
'd3011aef-3297-401c-88=
d7-65079e05dd4d', 'imageID': '272b7bb5-38e6-41b3-9da4-4cc278873fbf',
'specP=
arams': {}, 'readonly': 'false', 'domainID':
'8c8ad4f8-f187-410c-82a7-2beb7=
9a51a30', 'optional': 'false', 'deviceId':
'272b7bb5-38e6-41b3-9da4-4cc2788=
73fbf', 'address': {'bus': '0x00', ' slot':
'0x05', ' domain': '0x0000', ' =
type': 'pci', ' function': '0x0'}, 'device':
'disk', 'shared': 'false', 'pr=
opagateErrors': 'off', 'type': 'disk'}, {'nicModel':
'pv', 'macAddr': '52:5=
4:00:6d:ce:c8', 'linkActive': 'true', 'network': 'VM',
'custom': {}, 'filte=
r': 'vdsm-no-mac-spoofing', 'specParams': {}, 'deviceId':
'78c714a7-9bc5-46=
4b-85ae-328d29ba0b50', 'address': {'bus': '0x00', '
slot': '0x03', ' domain=
': '0x0000', ' type': 'pci', ' function':
'0x0'}, 'device': 'bridge', 'type=
': 'interface'}], 'spiceSecureChannels':
'smain,sinputs,scursor,splayback,s=
record,sdisplay,susbredir,ssmartcard', 'display': 'vnc'},) {} flowID
[574ec=
4d2]<br />Thread-867485::INFO::2013-11-26 14:58:52,509::API::641::vds::(_ge=
tNetworkIp) network None: using 0<br />Thread-867485::INFO::2013-11-26 14:5=
8:52,509::clientIF::366::vds::(createVm) vmContainerLock acquired by vm 879=
8d0da-a82c-4bcf-b41a-7e3fe1c613ef<br />Thread-867485::DEBUG::2013-11-26 14:=
58:52,515::clientIF::380::vds::(createVm) Total desktops after creation of =
8798d0da-a82c-4bcf-b41a-7e3fe1c613ef is 5<br />Thread-867486::DEBUG::2013-1=
1-26 14:58:52,516::vm::2015::vm.Vm::(_startUnderlyingVm) vmId=3D`8798d0da-a=
82c-4bcf-b41a-7e3fe1c613ef`::Start<br />Thread-867485::DEBUG::2013-11-26 14=
:58:52,516::BindingXMLRPC::986::vds::(wrapper) return vmCreate with {'statu=
s': {'message': 'Done', 'code': 0}, 'vmList':
{'status': 'WaitForLaunch', '=
acpiEnable': 'true', 'emulatedMachine': 'rhel6.4.0',
'tabletEnable': 'true'=
, 'pid': '0', 'memGuaranteedSize': 512, 'timeOffset':
'1', 'keyboardLayout'=
: 'de', 'displayPort': '-1', 'displaySecurePort':
'-1', 'spiceSslCipherSuit=
e': 'DEFAULT', 'cpuType': 'Nehalem', 'smp':
'1', 'clientIp': '', 'nicModel'=
: 'rtl8139,pv', 'smartcardEnable': 'false', 'kvmEnable':
'true', 'pitReinje=
ction': 'false', 'vmId':
'8798d0da-a82c-4bcf-b41a-7e3fe1c613ef', 'transpare=
ntHugePages': 'true', 'devices': [{'device': 'cirrus',
'specParams': {'vram=
': '65536'}, 'type': 'video', 'deviceId':
'bf71f555-dc86-417b-9649-b06083b8=
63b8', 'address': {'bus': '0x00', ' slot':
'0x02', ' domain': '0x0000', ' t=
ype': 'pci', ' function': '0x0'}}, {'index':
'2', 'iface': 'ide', 'address'=
: {' controller': '0', ' target': '0', 'unit':
'0', ' bus': '1', ' type': '=
drive'}, 'specParams': {'path': ''}, 'readonly':
'true', 'deviceId': '865f4=
2a1-f64a-49cd-a706-76bc1bea8517', 'path': '', 'device':
'cdrom', 'shared': =
'false', 'type': 'disk'}, {'index': 0, 'iface':
'virtio', 'format': 'raw', =
'bootOrder': '1', 'poolID':
'5849b030-626e-47cb-ad90-3ce782d831b3', 'volume=
ID': 'd3011aef-3297-401c-88d7-65079e05dd4d', 'imageID':
'272b7bb5-38e6-41b3=
-9da4-4cc278873fbf', 'specParams': {}, 'readonly': 'false',
'domainID': '8c=
8ad4f8-f187-410c-82a7-2beb79a51a30', 'optional': 'false',
'deviceId': '272b=
7bb5-38e6-41b3-9da4-4cc278873fbf', 'address': {'bus': '0x00',
' slot': '0x0=
5', ' domain': '0x0000', ' type': 'pci', '
function': '0x0'}, 'device': 'di=
sk', 'shared': 'false', 'propagateErrors': 'off',
'type': 'disk'}, {'nicMod=
el': 'pv', 'macAddr': '52:54:00:6d:ce:c8',
'linkActive': 'true', 'network':=
'VM', 'custom': {}, 'filter': 'vdsm-no-mac-spoofing',
'specParams': {}, 'd=
eviceId': '78c714a7-9bc5-464b-85ae-328d29ba0b50', 'address':
{'bus': '0x00'=
, ' slot': '0x03', ' domain': '0x0000', ' type':
'pci', ' function': '0x0'}=
, 'device': 'bridge', 'type': 'interface'}],
'custom': {'device_99b583e9-90=
30-40af-bb41-55d62a4a6b6adevice_5b94ca77-fab8-41b4-b286-311dee724813device_=
c3d8dcbf-d977-4d4d-8240-35b973ee00b9': 'VmDevice {vmId=3D8798d0da-a82c-4bcf=
-b41a-7e3fe1c613ef, deviceId=3Dc3d8dcbf-d977-4d4d-8240-35b973ee00b9, device=
=3Dscsi, type=3DCONTROLLER, bootOrder=3D0, specParams=3D{}, address=3D{bus=
=3D0x00, domain=3D0x0000, type=3Dpci, slot=3D0x04, function=3D0x0}, managed=
=3Dfalse, plugged=3Dtrue, readOnly=3Dfalse, deviceAlias=3Dscsi0, customProp=
erties=3D{}}', 'device_99b583e9-9030-40af-bb41-55d62a4a6b6a': 'VmDevice
{vm=
Id=3D8798d0da-a82c-4bcf-b41a-7e3fe1c613ef, deviceId=3D99b583e9-9030-40af-bb=
41-55d62a4a6b6a, device=3Dunix, type=3DCHANNEL, bootOrder=3D0, specParams=
=3D{}, address=3D{port=3D1, bus=3D0, controller=3D0, type=3Dvirtio-serial},=
managed=3Dfalse, plugged=3Dtrue, readOnly=3Dfalse, deviceAlias=3Dchannel0,=
customProperties=3D{}}', 'device_99b583e9-9030-40af-bb41-55d62a4a6b6adevic=
e_5b94ca77-fab8-41b4-b286-311dee724813device_c3d8dcbf-d977-4d4d-8240-35b973=
ee00b9device_839371b0-1967-4435-910e-0d8e1c980850device_920282ca-79c2-4abf-=
b1f2-7425f16f7820': 'VmDevice {vmId=3D8798d0da-a82c-4bcf-b41a-7e3fe1c613ef,=
deviceId=3D920282ca-79c2-4abf-b1f2-7425f16f7820, device=3Dvirtio-serial, t=
ype=3DCONTROLLER, bootOrder=3D0, specParams=3D{}, address=3D{bus=3D0x00, do=
main=3D0x0000, type=3Dpci, slot=3D0x06, function=3D0x0}, managed=3Dfalse, p=
lugged=3Dtrue, readOnly=3Dfalse, deviceAlias=3Dvirtio-serial0, customProper=
ties=3D{}}', 'device_99b583e9-9030-40af-bb41-55d62a4a6b6adevice_5b94ca77-fa=
b8-41b4-b286-311dee724813device_c3d8dcbf-d977-4d4d-8240-35b973ee00b9device_=
839371b0-1967-4435-910e-0d8e1c980850': 'VmDevice {vmId=3D8798d0da-a82c-4bcf=
-b41a-7e3fe1c613ef, deviceId=3D839371b0-1967-4435-910e-0d8e1c980850, device=
=3Dide, type=3DCONTROLLER, bootOrder=3D0, specParams=3D{}, address=3D{bus=
=3D0x00, domain=3D0x0000, type=3Dpci, slot=3D0x01, function=3D0x1}, managed=
=3Dfalse, plugged=3Dtrue, readOnly=3Dfalse, deviceAlias=3Dide0, customPrope=
rties=3D{}}', 'device_99b583e9-9030-40af-bb41-55d62a4a6b6adevice_5b94ca77-f=
ab8-41b4-b286-311dee724813': 'VmDevice {vmId=3D8798d0da-a82c-4bcf-b41a-7e3f=
e1c613ef, deviceId=3D5b94ca77-fab8-41b4-b286-311dee724813, device=3Dunix, t=
ype=3DCHANNEL, bootOrder=3D0, specParams=3D{}, address=3D{port=3D2, bus=3D0=
, controller=3D0, type=3Dvirtio-serial}, managed=3Dfalse, plugged=3Dtrue, r=
eadOnly=3Dfalse, deviceAlias=3Dchannel1, customProperties=3D{}}'}, 'vmType'=
: 'kvm', 'memSize': 1024, 'displayIp': '0',
'spiceSecureChannels': 'smain,s=
inputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard', 'smpCoresP=
erSocket': '1', 'vmName':<br />'vm01',
'display': 'vnc', 'nice': '0'}}<br /=
Thread-867486::DEBUG::2013-11-26
14:58:52,519::vm::2019::vm.Vm::(_startUnd=
erlyingVm)
vmId=3D`8798d0da-a82c-4bcf-b41a-7e3fe1c613ef`::_ongoingCreations=
acquired<br />Thread-867486::INFO::2013-11-26 14:58:52,522::vm::2815::vm.V=
m::(_run) vmId=3D`8798d0da-a82c-4bcf-b41a-7e3fe1c613ef`::VM wrapper has sta=
rted<br />Thread-867486::DEBUG::2013-11-26 14:58:52,527::task::579::TaskMan=
ager.Task::(_updateState) Task=3D`e64eb271-e389-4057-81f7-1148059464d7`::mo=
ving from state init -> state preparing<br />Thread-867486::INFO::2013-1=
1-26 14:58:52,530::logUtils::44::dispatcher::(wrapper) Run and protect: get=
VolumeSize(sdUUID=3D'8c8ad4f8-f187-410c-82a7-2beb79a51a30', spUUID=3D'5849b=
030-626e-47cb-ad90-3ce782d831b3', imgUUID=3D'272b7bb5-38e6-41b3-9da4-4cc278=
873fbf', volUUID=3D'd3011aef-3297-401c-88d7-65079e05dd4d',
options=3DNone)<=
br />Thread-867486::DEBUG::2013-11-26 14:58:52,534::lvm::415::OperationMute=
x::(_reloadlvs) Operation 'lvm reload operation' got the operation mutex<br=
/>Thread-867486::DEBUG::2013-11-26 14:58:52,539::lvm::311::Storage.Misc.ex=
cCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm lvs --config " devices { preferred_=
names =3D [\\"^/dev/mapper/\\"] ignore_suspended_devices=3D1 write_cache_st=
ate=3D0 disable_after_error_count=3D3 filter =3D [ \'a|/dev/mapper/36001405=
1fd69751de087d46f1da5aadb|/dev/mapper/360014056ce3d140de6a5d4fffd9218da|/de=
v/mapper/360014056db0fc0fdcda7d4a27da043d5|/dev/mapper/36001405917dfc0dd080=
9d41cfd86c9d4|/dev/mapper/3600508b1001cd6f84303d050b8fb5a80|\', \'r|.*|\' ]=
} global { locking_type=3D1
prioritise_write_locks=3D1&n=
bsp; wait_for_locks=3D1 } backup { retain_min =3D 50 reta=
in_days =3D 0 } " --noheadings --units b --nosuffix --separator | -o uuid,n=
ame,vg_name,attr,size,seg_start_pe,devices,tags 8c8ad4f8-f187-410c-82a7-2be=
b79a51a30' (cwd None)<br />Thread-867486::DEBUG::2013-11-26 14:58:52,588::l=
vm::311::Storage.Misc.excCmd::(cmd) SUCCESS: <err> =3D '';
<rc>=
=3D 0<br />Thread-867486::DEBUG::2013-11-26 14:58:52,623::lvm::448::Operat=
ionMutex::(_reloadlvs) Operation 'lvm reload operation' released the operat=
ion mutex<br />Thread-867486::INFO::2013-11-26 14:58:52,623::logUtils::47::=
dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'tr=
uesize': '42949672960', 'apparentsize': '42949672960'}<br
/>Thread-867486::=
DEBUG::2013-11-26 14:58:52,624::task::1168::TaskManager.Task::(prepare) Tas=
k=3D`e64eb271-e389-4057-81f7-1148059464d7`::finished: {'truesize': '4294967=
2960', 'apparentsize': '42949672960'}<br
/>Thread-867486::DEBUG::2013-11-26=
14:58:52,624::task::579::TaskManager.Task::(_updateState) Task=3D`e64eb271=
-e389-4057-81f7-1148059464d7`::moving from state preparing -> state fini=
shed<br />Thread-867486::DEBUG::2013-11-26 14:58:52,624::resourceManager::9=
39::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resour=
ces {}<br />Thread-867486::DEBUG::2013-11-26 14:58:52,625::resourceManager:=
:976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}<br />T=
hread-867486::DEBUG::2013-11-26 14:58:52,625::task::974::TaskManager.Task::=
(_decref) Task=3D`e64eb271-e389-4057-81f7-1148059464d7`::ref 0 aborting Fal=
se<br />Thread-867486::INFO::2013-11-26 14:58:52,625::clientIF::325::vds::(=
prepareVolumePath) prepared volume path:<br />Thread-867486::DEBUG::2013-11=
-26 14:58:52,626::task::579::TaskManager.Task::(_updateState) Task=3D`e0d90=
71f-a343-400e-865d-81656dd8862b`::moving from state init -> state prepar=
ing<br />Thread-867486::INFO::2013-11-26 14:58:52,626::logUtils::44::dispat=
cher::(wrapper) Run and protect: prepareImage(sdUUID=3D'8c8ad4f8-f187-410c-=
82a7-2beb79a51a30', spUUID=3D'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUI=
D=3D'272b7bb5-38e6-41b3-9da4-4cc278873fbf', volUUID=3D'd3011aef-3297-401c-8=
8d7-65079e05dd4d')<br />Thread-867486::DEBUG::2013-11-26 14:58:52,627::reso=
urceManager::197::ResourceManager.Request::(__init__) ResName=3D`Storage.8c=
8ad4f8-f187-410c-82a7-2beb79a51a30`ReqID=3D`664dc122-58c1-49d1-a03e-faa2182=
f42da`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3240'
at=
'prepareImage'<br />Thread-867486::DEBUG::2013-11-26
14:58:52,627::resourc=
eManager::541::ResourceManager::(registerResource) Trying to register resou=
rce 'Storage.8c8ad4f8-f187-410c-82a7-2beb79a51a30' for lock type
'shared'<b=
r />Thread-867486::DEBUG::2013-11-26 14:58:52,628::resourceManager::600::Re=
sourceManager::(registerResource) Resource 'Storage.8c8ad4f8-f187-410c-82a7=
-2beb79a51a30' is free. Now locking as 'shared' (1 active user)<br
/>Thread=
-867486::DEBUG::2013-11-26 14:58:52,628::resourceManager::237::ResourceMana=
ger.Request::(grant) ResName=3D`Storage.8c8ad4f8-f187-410c-82a7-2beb79a51a3=
0`ReqID=3D`664dc122-58c1-49d1-a03e-faa2182f42da`::Granted request<br />Thre=
ad-867486::DEBUG::2013-11-26 14:58:52,629::task::811::TaskManager.Task::(re=
sourceAcquired) Task=3D`e0d9071f-a343-400e-865d-81656dd8862b`::_resourcesAc=
quired: Storage.8c8ad4f8-f187-410c-82a7-2beb79a51a30 (shared)<br />Thread-8=
67486::DEBUG::2013-11-26 14:58:52,629::task::974::TaskManager.Task::(_decre=
f) Task=3D`e0d9071f-a343-400e-865d-81656dd8862b`::ref 1 aborting False<br /=
Thread-867486::DEBUG::2013-11-26
14:58:52,635::blockVolume::588::Storage.M=
isc.excCmd::(getMetadata) '/bin/dd
iflag=3Ddirect skip=3D23 bs=3D512 if=3D/=
dev/8c8ad4f8-f187-410c-82a7-2beb79a51a30/metadata count=3D1' (cwd None)<br =
/>Thread-867486::DEBUG::2013-11-26 14:58:52,644::blockVolume::588::Storage.=
Misc.excCmd::(getMetadata) SUCCESS: <err> =3D '1+0 records in\n1+0 re=
cords out\n512 bytes (512 B) copied, 0.000281928 s, 1.8 MB/s\n'; <rc>=
=3D 0<br />Thread-867486::DEBUG::2013-11-26 14:58:52,644::misc::288::Stora=
ge.Misc::(validateDDBytes) err: ['1+0 records in', '1+0 records out',
'512 =
bytes (512 B) copied, 0.000281928 s, 1.8 MB/s'], size: 512<br />Thread-8674=
86::INFO::2013-11-26 14:58:52,645::image::215::Storage.Image::(getChain) sd=
UUID=3D8c8ad4f8-f187-410c-82a7-2beb79a51a30 imgUUID=3D272b7bb5-38e6-41b3-9d=
a4-4cc278873fbf chain=3D[<storage.blockVolume.BlockVolume object at 0x14=
f6ad0>]<br />Thread-867486::DEBUG::2013-11-26 14:58:52,646::lvm::311::St=
orage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm lvchange --config " de=
vices { preferred_names =3D [\\"^/dev/mapper/\\"] ignore_suspended_devices=
=3D1 write_cache_state=3D0 disable_after_error_count=3D3 filter =3D [ \'a|/=
dev/mapper/360014051fd69751de087d46f1da5aadb|/dev/mapper/360014056ce3d140de=
6a5d4fffd9218da|/dev/mapper/360014056db0fc0fdcda7d4a27da043d5|/dev/mapper/3=
6001405917dfc0dd0809d41cfd86c9d4|/dev/mapper/3600508b1001cd6f84303d050b8fb5=
a80|\', \'r|.*|\' ] } global { locking_type=3D1
prioritis=
e_write_locks=3D1 wait_for_locks=3D1 } backup { retain_mi=
n =3D 50 retain_days =3D 0 } " --autobackup n --available y 8c8ad4f8-=
f187-410c-82a7-2beb79a51a30/d3011aef-3297-401c-88d7-65079e05dd4d' (cwd None=
)<br />Thread-867486::DEBUG::2013-11-26 14:58:52,942::lvm::311::Storage.Mis=
c.excCmd::(cmd) SUCCESS: <err> =3D ''; <rc> =3D
0<br />Thread-8=
67486::DEBUG::2013-11-26 14:58:52,943::lvm::499::OperationMutex::(_invalida=
telvs) Operation 'lvm invalidate operation' got the operation mutex<br
/>Th=
read-867486::DEBUG::2013-11-26 14:58:52,943::lvm::511::OperationMutex::(_in=
validatelvs) Operation 'lvm invalidate operation' released the operation mu=
tex<br />Thread-867486::DEBUG::2013-11-26 14:58:52,943::lvm::415::Operation=
Mutex::(_reloadlvs) Operation 'lvm reload operation' got the operation mute=
x<br />Thread-867486::DEBUG::2013-11-26 14:58:52,944::lvm::311::Storage.Mis=
c.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm lvs --config " devices { prefer=
red_names =3D [\\"^/dev/mapper/\\"] ignore_suspended_devices=3D1 write_cach=
e_state=3D0 disable_after_error_count=3D3 filter =3D [ \'a|/dev/mapper/3600=
14051fd69751de087d46f1da5aadb|/dev/mapper/360014056ce3d140de6a5d4fffd9218da=
|/dev/mapper/360014056db0fc0fdcda7d4a27da043d5|/dev/mapper/36001405917dfc0d=
d0809d41cfd86c9d4|/dev/mapper/3600508b1001cd6f84303d050b8fb5a80|\', \'r|.*|=
\' ] } global { locking_type=3D1
prioritise_write_locks=
=3D1 wait_for_locks=3D1 } backup { retain_min =3D
50 =
; retain_days =3D 0 } " --noheadings --units b --nosuffix --separator | -o =
uuid,name,vg_name,attr,size,seg_start_pe,devices,tags 8c8ad4f8-f187-410c-82=
a7-2beb79a51a30' (cwd None)<br />Thread-867486::DEBUG::2013-11-26 14:58:53,=
242::lvm::311::Storage.Misc.excCmd::(cmd) SUCCESS: <err> =3D '';
<=
rc> =3D 0<br />Thread-867486::DEBUG::2013-11-26 14:58:53,277::lvm::448::=
OperationMutex::(_reloadlvs) Operation 'lvm reload operation' released the =
operation mutex<br />Thread-867486::DEBUG::2013-11-26 14:58:53,283::blockVo=
lume::588::Storage.Misc.excCmd::(getMetadata) '/bin/dd iflag=3Ddirect skip=
=3D23 bs=3D512 if=3D/dev/8c8ad4f8-f187-410c-82a7-2beb79a51a30/metadata coun=
t=3D1' (cwd None)<br />Thread-867486::DEBUG::2013-11-26 14:58:53,292::block=
Volume::588::Storage.Misc.excCmd::(getMetadata) SUCCESS: <err> =3D '1=
+0 records in\n1+0 records out\n512 bytes (512 B) copied, 0.000298328 s, 1.=
7 MB/s\n'; <rc> =3D 0<br />Thread-867486::DEBUG::2013-11-26
14:58:53,=
292::misc::288::Storage.Misc::(validateDDBytes) err: ['1+0 records in', '1+=
0 records out', '512 bytes (512 B) copied, 0.000298328 s, 1.7 MB/s'], size:=
512<br />Thread-867486::INFO::2013-11-26 14:58:53,293::logUtils::47::dispa=
tcher::(wrapper) Run and protect: prepareImage, Return response: {'info': {=
'path': '/rhev/data-center/5849b030-626e-47cb-ad90-3ce782d831b3/8c8ad4f8-f1=
87-410c-82a7-2beb79a51a30/images/272b7bb5-38e6-41b3-9da4-4cc278873fbf/d3011=
aef-3297-401c-88d7-65079e05dd4d', 'volType': 'path'}, 'path':
'/rhev/data-c=
enter/5849b030-626e-47cb-ad90-3ce782d831b3/8c8ad4f8-f187-410c-82a7-2beb79a5=
1a30/images/272b7bb5-38e6-41b3-9da4-4cc278873fbf/d3011aef-3297-401c-88d7-65=
079e05dd4d', 'chain': [{'path':
'/rhev/data-center/5849b030-626e-47cb-ad90-=
3ce782d831b3/8c8ad4f8-f187-410c-82a7-2beb79a51a30/images/272b7bb5-38e6-41b3=
-9da4-4cc278873fbf/d3011aef-3297-401c-88d7-65079e05dd4d', 'domainID':
'8c8a=
d4f8-f187-410c-82a7-2beb79a51a30', 'vmVolInfo': {'path':
'/rhev/data-center=
/5849b030-626e-47cb-ad90-3ce782d831b3/8c8ad4f8-f187-410c-82a7-2beb79a51a30/=
images/272b7bb5-38e6-41b3-9da4-4cc278873fbf/d3011aef-3297-401c-88d7-65079e0=
5dd4d', 'volType': 'path'}, 'volumeID':
'd3011aef-3297-401c-88d7-65079e05dd=
4d', 'imageID': '272b7bb5-38e6-41b3-9da4-4cc278873fbf'}]}<br
/>Thread-86748=
6::DEBUG::2013-11-26 14:58:53,293::task::1168::TaskManager.Task::(prepare) =
Task=3D`e0d9071f-a343-400e-865d-81656dd8862b`::finished: {'info': {'path':
=
'/rhev/data-center/5849b030-626e-47cb-ad90-3ce782d831b3/8c8ad4f8-f187-410c-=
82a7-2beb79a51a30/images/272b7bb5-38e6-41b3-9da4-4cc278873fbf/d3011aef-3297=
-401c-88d7-65079e05dd4d', 'volType': 'path'}, 'path':
'/rhev/data-center/58=
49b030-626e-47cb-ad90-3ce782d831b3/8c8ad4f8-f187-410c-82a7-2beb79a51a30/ima=
ges/272b7bb5-38e6-41b3-9da4-4cc278873fbf/d3011aef-3297-401c-88d7-65079e05dd=
4d', 'chain': [{'path':
'/rhev/data-center/5849b030-626e-47cb-ad90-3ce782d8=
31b3/8c8ad4f8-f187-410c-82a7-2beb79a51a30/images/272b7bb5-38e6-41b3-9da4-4c=
c278873fbf/d3011aef-3297-401c-88d7-65079e05dd4d', 'domainID':
'8c8ad4f8-f18=
7-410c-82a7-2beb79a51a30', 'vmVolInfo': {'path':
'/rhev/data-center/5849b03=
0-626e-47cb-ad90-3ce782d831b3/8c8ad4f8-f187-410c-82a7-2beb79a51a30/images/2=
72b7bb5-38e6-41b3-9da4-4cc278873fbf/d3011aef-3297-401c-88d7-65079e05dd4d', =
'volType': 'path'}, 'volumeID':
'd3011aef-3297-401c-88d7-65079e05dd4d', 'im=
ageID': '272b7bb5-38e6-41b3-9da4-4cc278873fbf'}]}<br
/>Thread-867486::DEBUG=
::2013-11-26 14:58:53,293::task::579::TaskManager.Task::(_updateState) Task=
=3D`e0d9071f-a343-400e-865d-81656dd8862b`::moving from state preparing ->=
; state finished<br />Thread-867486::DEBUG::2013-11-26 14:58:53,294::resour=
ceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll reques=
ts {} resources {'Storage.8c8ad4f8-f187-410c-82a7-2beb79a51a30': < Resou=
rceRef 'Storage.8c8ad4f8-f187-410c-82a7-2beb79a51a30', isValid: 'True'
obj:=
'None'>}<br />Thread-867486::DEBUG::2013-11-26
14:58:53,294::resourceMa=
nager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}<=
br />Thread-867486::DEBUG::2013-11-26 14:58:53,294::resourceManager::615::R=
esourceManager::(releaseResource) Trying to release resource 'Storage.8c8ad=
4f8-f187-410c-82a7-2beb79a51a30'<br />Thread-867486::DEBUG::2013-11-26 14:5=
8:53,295::resourceManager::634::ResourceManager::(releaseResource) Released=
resource 'Storage.8c8ad4f8-f187-410c-82a7-2beb79a51a30' (0 active users)<b=
r />Thread-867486::DEBUG::2013-11-26 14:58:53,295::resourceManager::640::Re=
sourceManager::(releaseResource) Resource 'Storage.8c8ad4f8-f187-410c-82a7-=
2beb79a51a30' is free, finding out if anyone is waiting for it.<br />Thread=
-867486::DEBUG::2013-11-26 14:58:53,295::resourceManager::648::ResourceMana=
ger::(releaseResource) No one is waiting for resource 'Storage.8c8ad4f8-f18=
7-410c-82a7-2beb79a51a30', Clearing records.<br />Thread-867486::DEBUG::201=
3-11-26 14:58:53,296::task::974::TaskManager.Task::(_decref) Task=3D`e0d907=
1f-a343-400e-865d-81656dd8862b`::ref 0 aborting False<br />Thread-867486::I=
NFO::2013-11-26 14:58:53,296::clientIF::325::vds::(prepareVolumePath) prepa=
red volume path: /rhev/data-center/5849b030-626e-47cb-ad90-3ce782d831b3/8c8=
ad4f8-f187-410c-82a7-2beb79a51a30/images/272b7bb5-38e6-41b3-9da4-4cc278873f=
bf/d3011aef-3297-401c-88d7-65079e05dd4d<br />Thread-867486::DEBUG::2013-11-=
26 14:58:53,318::utils::486::root::(execCmd) '/usr/libexec/vdsm/hooks/befor=
e_vm_start/50_smbios' (cwd None)<br />Thread-867486::DEBUG::2013-11-26 14:5=
8:53,400::utils::505::root::(execCmd) SUCCESS: <err> =3D '';
<rc&g=
t; =3D 0<br />Thread-867486::INFO::2013-11-26 14:58:53,401::hooks::88::root=
::(_runHooksDir)<br />Thread-867486::DEBUG::2013-11-26 14:58:53,401::vm::28=
72::vm.Vm::(_run) vmId=3D`8798d0da-a82c-4bcf-b41a-7e3fe1c613ef`::<?xml v=
ersion=3D"1.0" encoding=3D"utf-8"?><br /><domain
type=3D"kvm"><br =
/>
<name>vm01</name><=
br />
<uuid>8798d0da-a82c-4=
bcf-b41a-7e3fe1c613ef</uuid><br
/>  =
; <memory>1048576</memory><br
/> &=
nbsp;
<currentMemory>1048576</currentMemory><br />&=
nbsp;
<vcpu>1</vcpu><br />&=
nbsp;
<memtune><br /> =
&nb=
sp; <min_guarantee>524288</min_guarantee><br
/> &nbs=
p; </memtune><br
/> &n=
bsp; <devices><br
/> &=
nbsp;
<channel type=3D"u=
nix"><br
/> &=
nbsp; &nbs=
p; <target name=3D"com.redhat.rhevm.vdsm"
type=3D"virtio"/><br />&nbs=
p; &=
nbsp;
<source mode=
=3D"bind"
path=3D"/var/lib/libvirt/qemu/channels/8798d0da-a82c-4bcf-b41a-7e=
3fe1c613ef.com.redhat.rhevm.vdsm"/><br
/> &=
nbsp;
</channel>=
;<br
/> &n=
bsp; <channel type=3D"unix"><br
/>  =
; &n=
bsp; <target
name=3D"org.qemu.=
guest_agent.0" type=3D"virtio"/><br
/> &nbs=
p; &=
nbsp; <source mode=3D"bind"
path=3D"/var/lib/lib=
virt/qemu/channels/8798d0da-a82c-4bcf-b41a-7e3fe1c613ef.org.qemu.guest_agen=
t.0"/><br
/> =
</channel><br
/> &nbs=
p;
<in=
put bus=3D"usb" type=3D"tablet"/><br
/> &nb=
sp;
<graphics auto=
port=3D"yes" keymap=3D"de" listen=3D"0"
passwd=3D"*****" passwdValidTo=3D"1=
970-01-01T00:00:01" port=3D"-1" type=3D"vnc"/><br
/> &n=
bsp;
<=
video><br
/> =
&nb=
sp; <address bus=3D"0x00" domain=3D"0x0000"
function=3D"0x0" slot=3D"0x0=
2" type=3D"pci"/><br
/> &=
nbsp; &nbs=
p; <model heads=3D"1" type=3D"cirrus"
vram=3D"65536"/><br=
/> =
</video><br
/> =
<interface type=
=3D"bridge"><br
/> =
&nb=
sp; <address bus=3D"0x00" domain=3D"0x0000"
function=3D"0x0" slot=
=3D"0x03" type=3D"pci"/><br
/> =
&nb=
sp; <mac
address=3D"52:54:00:6d:ce:c8"/><br /> =
; &n=
bsp;
<model type=
=3D"virtio"/><br
/>  =
; &n=
bsp; <source bridge=3D"VM"/><br
/>  =
; &n=
bsp; <filterref
filter=3D"vdsm-no-mac-spoo=
fing"/><br
/>  =
; &n=
bsp; <link state=3D"up"/><br
/> &n=
bsp;
</interface><br =
/> &=
nbsp; <disk device=3D"cdrom"
snapshot=3D"no" type=3D"file"&g=
t;<br
/> &=
nbsp;
<=
;address bus=3D"1" controller=3D"0" target=3D"0"
type=3D"drive" unit=3D"0"/=
><br
/>  =
;
&=
lt;source file=3D"" startupPolicy=3D"optional"/><br
/> =
&nb=
sp; <target
bus=3D"ide" dev=3D=
"hdc"/><br
/>  =
; &n=
bsp; <readonly/><br
/>  =
; &n=
bsp; <serial/><br
/> &=
nbsp;
</disk><br />&n=
bsp;  =
; <disk device=3D"disk" snapshot=3D"no"
type=3D"block"><b=
r
/>  =
;
<add=
ress bus=3D"0x00" domain=3D"0x0000" function=3D"0x0"
slot=3D"0x05" type=3D"=
pci"/><br
/> =
&nb=
sp; <source dev=3D"/rhev/data-center/5849b030-626e-47cb-ad90-3ce782d831b=
3/8c8ad4f8-f187-410c-82a7-2beb79a51a30/images/272b7bb5-38e6-41b3-9da4-4cc27=
8873fbf/d3011aef-3297-401c-88d7-65079e05dd4d"/><br
/> &=
nbsp; &nbs=
p; <target
bus=3D"virtio" dev=
=3D"vda"/><br
/> &n=
bsp;  =
;
<serial>272b7bb5-38e6-41b3-9da4-4cc278873fbf</serial><b=
r
/>  =
;
<boo=
t order=3D"1"/><br
/> &nb=
sp; =
<driver cache=3D"none"
error_policy=3D"stop" io=3D"native" =
name=3D"qemu" type=3D"raw"/><br
/> &n=
bsp;
</disk><br />&nb=
sp; =
<memballoon model=3D"none"/><br
/> &nbs=
p; </devices><br
/> &n=
bsp; <os><br
/> =
<type
arch=3D"x86_64" machine=
=3D"rhel6.4.0">hvm</type><br
/>  =
;
<smbios mode=3D"=
sysinfo"/><br
/>
</os><b=
r />
<sysinfo type=3D"smbios"&=
gt;<br
/> =
<system><br
/> =
&nb=
sp; <entry
name=3D"manufacturer">oVirt&=
lt;/entry><br
/> &n=
bsp;  =
; <entry name=3D"product">oVirt
Node</entry><br /> &=
nbsp; &nbs=
p;
<entry name=3D"=
version">6-4.el6.centos.10</entry><br
/> &n=
bsp;  =
; <entry
name=3D"serial">32393735=
-3933-5A43-4A32-34333046564B</entry><br
/> &nb=
sp; =
<entry
name=3D"uuid">8798d0da-a8=
2c-4bcf-b41a-7e3fe1c613ef</entry><br
/> =
</system>=
;<br />
</sysinfo><br />&nb=
sp; <clock
adjustment=3D"1" offset=
=3D"variable"><br
/> &nbs=
p; <timer
name=3D"rtc" tickpolicy=3D=
"catchup"/><br
/>
</clock&g=
t;<br />
<features><br />&n=
bsp;  =
; <acpi/><br
/> =
</features><br
/> <cpu =
match=3D"exact"><br
/> &n=
bsp;
<model>Nehalem</model>=
<br
/> &nb=
sp; <topology cores=3D"1"
sockets=3D"1" threads=3D"1"/=
><br />
</cpu><br /><=
/domain><br /><br />Thread-166407::DEBUG::2013-11-26
14:58:53,588::block=
SD::594::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=3Ddirect if=3D/=
dev/8c8ad4f8-f187-410c-82a7-2beb79a51a30/metadata bs=3D4096 count=3D1' (cwd=
None)<br />Thread-166407::DEBUG::2013-11-26 14:58:53,599::blockSD::594::St=
orage.Misc.excCmd::(getReadDelay) SUCCESS: <err> =3D '1+0 records in\=
n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000345562 s, 11.9 MB/s\n'; =
<rc> =3D 0<br />Thread-24::DEBUG::2013-11-26
14:58:53,791::fileSD::23=
8::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=3Ddirect<br />if=3D/r=
hev/data-center/mnt/engine.privat.com:_export_VMs/48055e27-f1ca-466a-8a2c-e=
191c34f0226/dom_md/metadata bs=3D4096 count=3D1' (cwd None)<br />Thread-24:=
:DEBUG::2013-11-26 14:58:53,801::fileSD::238::Storage.Misc.excCmd::(getRead=
Delay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n349 bytes=
(349 B) copied, 0.000683955 s, 510 kB/s\n'; <rc> =3D 0<br
/>libvirtE=
ventLoop::DEBUG::2013-11-26 14:58:54,094::vm::4724::vm.Vm::(_onLibvirtLifec=
ycleEvent) vmId=3D`8798d0da-a82c-4bcf-b41a-7e3fe1c613ef`::event Started det=
ail 0 opaque None<br />Thread-867486::DEBUG::2013-11-26 14:58:54,248::sampl=
ing::285::vm.Vm::(start) vmId=3D`8798d0da-a82c-4bcf-b41a-7e3fe1c613ef`::Sta=
rt statistics collection<br />Thread-867488::DEBUG::2013-11-26 14:58:54,249=
::sampling::314::vm.Vm::(run) vmId=3D`8798d0da-a82c-4bcf-b41a-7e3fe1c613ef`=
::Stats thread started<br />Thread-867486::DEBUG::2013-11-26 14:58:54,251::=
vmChannels::194::vds::(register) Add fileno 51 to listener's channels.<br /=
Thread-867488::DEBUG::2013-11-26
14:58:54,253::task::579::TaskManager.Task=
::(_updateState)
Task=3D`c5c6d816-7de8-4ab5-a5fa-a3fba225d797`::moving from=
state init -> state preparing<br />Thread-867488::INFO::2013-11-26 14:5=
8:54,253::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSiz=
e(sdUUID=3D'8c8ad4f8-f187-410c-82a7-2beb79a51a30', spUUID=3D'5849b030-626e-=
47cb-ad90-3ce782d831b3', imgUUID=3D'272b7bb5-38e6-41b3-9da4-4cc278873fbf', =
volUUID=3D'd3011aef-3297-401c-88d7-65079e05dd4d', options=3DNone)<br
/>Thre=
ad-867486::WARNING::2013-11-26 14:58:54,253::vm::3326::vm.Vm::(_readPauseCo=
de) vmId=3D`8798d0da-a82c-4bcf-b41a-7e3fe1c613ef`::_readPauseCode unsupport=
ed by libvirt vm<br />Thread-867488::INFO::2013-11-26 14:58:54,255::logUtil=
s::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return respons=
e: {'truesize': '42949672960', 'apparentsize':
'42949672960'}<br />Thread-8=
67488::DEBUG::2013-11-26 14:58:54,256::task::1168::TaskManager.Task::(prepa=
re) Task=3D`c5c6d816-7de8-4ab5-a5fa-a3fba225d797`::finished: {'truesize': '=
42949672960', 'apparentsize': '42949672960'}<br
/>Thread-867488::DEBUG::201=
3-11-26 14:58:54,256::task::579::TaskManager.Task::(_updateState) Task=3D`c=
5c6d816-7de8-4ab5-a5fa-a3fba225d797`::moving from state preparing -> sta=
te finished<br />Thread-867488::DEBUG::2013-11-26 14:58:54,256::resourceMan=
ager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {}=
resources {}<br />Thread-867488::DEBUG::2013-11-26 14:58:54,257::resourceM=
anager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}=
<br />Thread-867488::DEBUG::2013-11-26 14:58:54,257::task::974::TaskManager=
.Task::(_decref) Task=3D`c5c6d816-7de8-4ab5-a5fa-a3fba225d797`::ref 0 abort=
ing False<br />Thread-867486::DEBUG::2013-11-26 14:58:54,263::vm::2036::vm.=
Vm::(_startUnderlyingVm) vmId=3D`8798d0da-a82c-4bcf-b41a-7e3fe1c613ef`::_on=
goingCreations released<br />VM Channels Listener::DEBUG::2013-11-26 14:58:=
54,694::vmChannels::102::vds::(_do_add_channels) fileno 51 was added to unc=
onnected channels.<br />VM Channels Listener::DEBUG::2013-11-26 14:58:54,69=
4::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 51.=
<br />VM Channels Listener::DEBUG::2013-11-26 14:58:54,695::guestIF::147::v=
m.Vm::(_connect) vmId=3D`8798d0da-a82c-4bcf-b41a-7e3fe1c613ef`::Attempting =
connection to /var/lib/libvirt/qemu/channels/8798d0da-a82c-4bcf-b41a-7e3fe1=
c613ef.com.redhat.rhevm.vdsm<br />VM Channels Listener::DEBUG::2013-11-26 1=
4:58:54,695::guestIF::150::vm.Vm::(_connect) vmId=3D`8798d0da-a82c-4bcf-b41=
a-7e3fe1c613ef`::Connected to /var/lib/libvirt/qemu/channels/8798d0da-a82c-=
4bcf-b41a-7e3fe1c613ef.com.redhat.rhevm.vdsm<br />VM Channels Listener::DEB=
UG::2013-11-26 14:58:54,695::vmChannels::144::vds::(_handle_unconnected) Co=
nnecting to fileno 51 succeeded.<br />Thread-867490::DEBUG::2013-11-26 14:5=
8:55,170::BindingXMLRPC::979::vds::(wrapper) client [192.168.1.29]::call vm=
GetStats with ('8798d0da-a82c-4bcf-b41a-7e3fe1c613ef',) {}<br
/>Thread-8674=
90::DEBUG::2013-11-26 14:58:55,170::vm::579::vm.Vm::(_getCpuStats) vmId=3D`=
8798d0da-a82c-4bcf-b41a-7e3fe1c613ef`::CPU stats not available: 'NoneType' =
object is unsubscriptable<br />Thread-867490::DEBUG::2013-11-26 14:58:55,17=
0::vm::613::vm.Vm::(_getNetworkStats) vmId=3D`8798d0da-a82c-4bcf-b41a-7e3fe=
1c613ef`::Network stats not available</span></span>
--========GMXBoundary242171385563631782200--
10:46 a.m.
----- Original Message -----
From: "Hans-Joachim" <rni(a)chef.net>
To: users(a)ovirt.org
Sent: Wednesday, November 27, 2013 4:47:11 PM
Subject: [Users] Problem starting VM in oVirt 3.3.1-2
Hello,
I'm running in troubles.....
After migrating the storage of an powered off VM to a different iSCSI
storage, my CentOS 4 VM does not start any more (well, it's not the reality,
but for the system the VM stays in Wait for launch for hours). In reality,
the VM starts on the node.
Hi,
we've already solve this issue and it probably be included in the next release.
a simple workaround:
either disable ballooning in the cluster (edit cluster -> Optimization -> uncheck
Enable balloon)
or enable ballooning for the vm (edit vm -> Resource Allocation -> check Memory
Balloon Device Enabled)
Thanks, Gilad.
Any hints?
My Config:
CentOS 6.4
oVirt 3.3.1-2
VDSM 4.12.1-4
engine.log
2013-11-26 14:58:50,171 INFO [org.ovirt.engine.core.bll.AsyncTaskManager]
(DefaultQuartzScheduler_Worker-46) Setting new tasks map. The map contains
now 0 tasks
2013-11-26 14:58:50,172 INFO [org.ovirt.engine.core.bll.AsyncTaskManager]
(DefaultQuartzScheduler_Worker-46) Cleared all tasks of pool
5849b030-626e-47cb-ad90-3ce782d831b3.
2013-11-26 14:58:52,106 INFO [org.ovirt.engine.core.bll.RunVmCommand]
(ajp--127.0.0.1-8702-2) [574ec4d2] Lock Acquired to object EngineLock
[exclusiveLocks= key: 8798d0da-a82c-4bcf-b41a-7e3fe1c613ef value: VM
, sharedLocks= ]
2013-11-26 14:58:52,124 INFO
[org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand]
(ajp--127.0.0.1-8702-2) [574ec4d2] START, IsVmDuringInitiatingVDSCommand(
vmId = 8798d0da-a82c-4bcf-b41a-7e3fe1c613ef), log id: 13e7aadf
2013-11-26 14:58:52,125 INFO
[org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand]
(ajp--127.0.0.1-8702-2) [574ec4d2] FINISH, IsVmDuringInitiatingVDSCommand,
return: false, log id: 13e7aadf
2013-11-26 14:58:52,251 INFO [org.ovirt.engine.core.bll.RunVmCommand]
(pool-6-thread-50) [574ec4d2] Running command: RunVmCommand internal: false.
Entities affected : ID: 8798d0da-a82c-4bcf-b41a-7e3fe1c613ef Type: VM
2013-11-26 14:58:52,406 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.IsoPrefixVDSCommand]
(pool-6-thread-50) [574ec4d2] START, IsoPrefixVDSCommand(HostName = HOST01,
HostId = b34d1e33-bdda-4ba8-9c23-0d136f372ad8,
storagePoolId=5849b030-626e-47cb-ad90-3ce782d831b3), log id: 1a6a3b22
2013-11-26 14:58:52,408 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.IsoPrefixVDSCommand]
(pool-6-thread-50) [574ec4d2] FINISH, IsoPrefixVDSCommand, return:
/rhev/data-center/mnt/engine.private.com:_var_lib_exports_iso/53a22027-fd2d-451b-8cd7-0e604fb8e460/images/11111111-1111-1111-1111-111111111111,
log id: 1a6a3b22
2013-11-26 14:58:52,441 INFO
[org.ovirt.engine.core.vdsbroker.CreateVmVDSCommand] (pool-6-thread-50)
[574ec4d2] START, CreateVmVDSCommand(HostName = HOST01, HostId =
b34d1e33-bdda-4ba8-9c23-0d136f372ad8,
vmId=8798d0da-a82c-4bcf-b41a-7e3fe1c613ef, vm=VM [vm01]), log id: 2da012df
2013-11-26 14:58:52,476 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand]
(pool-6-thread-50) [574ec4d2] START, CreateVDSCommand(HostName = HOST01,
HostId = b34d1e33-bdda-4ba8-9c23-0d136f372ad8,
vmId=8798d0da-a82c-4bcf-b41a-7e3fe1c613ef, vm=VM [vm01]), log id: 727a7bf7
2013-11-26 14:58:52,539 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand]
(pool-6-thread-50) [574ec4d2]
org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand
spiceSslCipherSuite=DEFAULT,memSize=1024,kvmEnable=true,smp=1,vmType=kvm,emulatedMachine=rhel6.4.0,keyboardLayout=de,memGuaranteedSize=512,pitReinjection=false,nice=0,display=vnc,smartcardEnable=false,tabletEnable=true,smpCoresPerSocket=1,spiceSecureChannels=smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard,timeOffset=1,transparentHugePages=true,vmId=8798d0da-a82c-4bcf-b41a-7e3fe1c613ef,devices=[Ljava.util.HashMap;@1030ba06,acpiEnable=true,vmName=vm01,cpuType=Nehalem,custom={device_99b583e9-9030-40af-bb41-55d62a4a6b6adevice_5b94ca77-fab8-41b4-b286-311dee724813=VmDevice
{vmId=8798d0da-a82c-4bcf-b41a-7e3fe1c613ef,
deviceId=5b94ca77-fab8-41b4-b286-311dee724813, device=unix, type=CHANNEL,
bootOrder=0, specParams={}, address={port=2, bus=0, controller=0,
type=virtio-serial}, managed=false, plugged=true, readOnly=false,
deviceAlias=channel1, customProperties={}},
device_99b583e9-9030-40af-bb41-55d62a4a6b6a=VmDevice
{vmId=8798d0da-a82c-4bcf-b41a-7e3fe1c613ef,
deviceId=99b583e9-9030-40af-bb41-55d62a4a6b6a, device=unix, type=CHANNEL,
bootOrder=0, specParams={}, address={port=1, bus=0, controller=0,
type=virtio-serial}, managed=false, plugged=true, readOnly=false,
deviceAlias=channel0, customProperties={}},
device_99b583e9-9030-40af-bb41-55d62a4a6b6adevice_5b94ca77-fab8-41b4-b286-311dee724813device_c3d8dcbf-d977-4d4d-8240-35b973ee00b9device_839371b0-1967-4435-910e-0d8e1c980850=VmDevice
{vmId=8798d0da-a82c-4bcf-b41a-7e3fe1c613ef,
deviceId=839371b0-1967-4435-910e-0d8e1c980850, device=ide, type=CONTROLLER,
bootOrder=0, specParams={}, address={bus=0x00, domain=0x0000, type=pci,
slot=0x01, function=0x1}, managed=false, plugged=true, readOnly=false,
deviceAlias=ide0, customProperties={}},
device_99b583e9-9030-40af-bb41-55d62a4a6b6adevice_5b94ca77-fab8-41b4-b286-311dee724813device_c3d8dcbf-d977-4d4d-8240-35b973ee00b9=VmDevice
{vmId=8798d0da-a82c-4bcf-b41a-7e3fe1c613ef,
deviceId=c3d8dcbf-d977-4d4d-8240-35b973ee00b9, device=scsi, type=CONTROLLER,
bootOrder=0, specParams={}, address={bus=0x00, domain=0x0000, type=pci,
slot=0x04, function=0x0}, managed=false, plugged=true, readOnly=false,
deviceAlias=scsi0, customProperties={}},
device_99b583e9-9030-40af-bb41-55d62a4a6b6adevice_5b94ca77-fab8-41b4-b286-311dee724813device_c3d8dcbf-d977-4d4d-8240-35b973ee00b9device_839371b0-1967-4435-910e-0d8e1c980850device_920282ca-79c2-4abf-b1f2-7425f16f7820=VmDevice
{vmId=8798d0da-a82c-4bcf-b41a-7e3fe1c613ef,
deviceId=920282ca-79c2-4abf-b1f2-7425f16f7820, device=virtio-serial,
type=CONTROLLER, bootOrder=0, specParams={}, address={bus=0x00,
domain=0x0000, type=pci, slot=0x06, function=0x0}, managed=false,
plugged=true, readOnly=false, deviceAlias=virtio-serial0,
customProperties={}}}
2013-11-26 14:58:52,552 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand]
(pool-6-thread-50) [574ec4d2] FINISH, CreateVDSCommand, log id: 727a7bf7
2013-11-26 14:58:52,567 INFO
[org.ovirt.engine.core.vdsbroker.CreateVmVDSCommand] (pool-6-thread-50)
[574ec4d2] FINISH, CreateVmVDSCommand, return: WaitForLaunch, log id:
2da012df
2013-11-26 14:58:52,568 INFO [org.ovirt.engine.core.bll.RunVmCommand]
(pool-6-thread-50) [574ec4d2] Lock freed to object EngineLock
[exclusiveLocks= key: 8798d0da-a82c-4bcf-b41a-7e3fe1c613ef value: VM
, sharedLocks= ]
2013-11-26 14:58:52,576 INFO
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(pool-6-thread-50) [574ec4d2] Correlation ID: 574ec4d2, Job ID:
d3d270e1-607b-4599-983a-1ef884e81a43, Call Stack: null, Custom Event ID: -1,
Message: VM vm01 was started by User01 (Host: HOST01).
2013-11-26 14:58:55,177 WARN [org.ovirt.engine.core.vdsbroker.VdsManager]
(DefaultQuartzScheduler_Worker-33) Failed to refresh VDS , vds =
b34d1e33-bdda-4ba8-9c23-0d136f372ad8 : HOST01, error =
java.lang.NullPointerException, continuing.: java.lang.NullPointerException
at
org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo.proceedBalloonCheck(VdsUpdateRunTimeInfo.java:1312)
[vdsbroker.jar:]
at
org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo.refreshVmStats(VdsUpdateRunTimeInfo.java:926)
[vdsbroker.jar:]
at
org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo.refreshVdsRunTimeInfo(VdsUpdateRunTimeInfo.java:502)
[vdsbroker.jar:]
at
org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo.Refresh(VdsUpdateRunTimeInfo.java:343)
[vdsbroker.jar:]
at org.ovirt.engine.core.vdsbroker.VdsManager.OnTimer(VdsManager.java:237)
[vdsbroker.jar:]
at sun.reflect.GeneratedMethodAccessor9.invoke(Unknown Source) [:1.7.0_45]
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[rt.jar:1.7.0_45]
at java.lang.reflect.Method.invoke(Method.java:606) [rt.jar:1.7.0_45]
at org.ovirt.engine.core.utils.timer.JobWrapper.execute(JobWrapper.java:60)
[scheduler.jar:]
at org.quartz.core.JobRunShell.run(JobRunShell.java:213) [quartz.jar:]
at
org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:557)
[quartz.jar:]
vdsm.log
Thread-867485::DEBUG::2013-11-26
14:58:52,504::BindingXMLRPC::979::vds::(wrapper) client [192.168.1.29]::call
vmCreate with ({'acpiEnable': 'true', 'emulatedMachine':
'rhel6.4.0',
'tabletEnable': 'true', 'vmId':
'8798d0da-a82c-4bcf-b41a-7e3fe1c613ef',
'memGuaranteedSize': 512, 'spiceSslCipherSuite': 'DEFAULT',
'timeOffset':
'1', 'cpuType': 'Nehalem', 'custom':
{'device_99b583e9-9030-40af-bb41-55d62a4a6b6adevice_5b94ca77-fab8-41b4-b286-311dee724813device_c3d8dcbf-d977-4d4d-8240-35b973ee00b9':
'VmDevice {vmId=8798d0da-a82c-4bcf-b41a-7e3fe1c613ef,
deviceId=c3d8dcbf-d977-4d4d-8240-35b973ee00b9, device=scsi, type=CONTROLLER,
bootOrder=0, specParams={}, address={bus=0x00, domain=0x0000, type=pci,
slot=0x04, function=0x0}, managed=false, plugged=true, readOnly=false,
deviceAlias=scsi0, customProperties={}}',
'device_99b583e9-9030-40af-bb41-55d62a4a6b6a': 'VmDevice
{vmId=8798d0da-a82c-4bcf-b41a-7e3fe1c613ef,
deviceId=99b583e9-9030-40af-bb41-55d62a4a6b6a, device=unix, type=CHANNEL,
bootOrder=0, specParams={}, address={port=1, bus=0, controller=0,
type=virtio-serial}, managed=false, plugged=true, readOnly=false,
deviceAlias=channel0, customProperties={}}',
'device_99b583e9-9030-40af-bb41-55d62a4a6b6adevice_5b94ca77-fab8-41b4-b286-311dee724813device_c3d8dcbf-d977-4d4d-8240-35b973ee00b9device_839371b0-1967-4435-910e-0d8e1c980850device_920282ca-79c2-4abf-b1f2-7425f16f7820':
'VmDevice {vmId=8798d0da-a82c-4bcf-b41a-7e3fe1c613ef,
deviceId=920282ca-79c2-4abf-b1f2-7425f16f7820, device=virtio-serial,
type=CONTROLLER, bootOrder=0, specParams={}, address={bus=0x00,
domain=0x0000, type=pci, slot=0x06, function=0x0}, managed=false,
plugged=true, readOnly=false, deviceAlias=virtio-serial0,
customProperties={}}',
'device_99b583e9-9030-40af-bb41-55d62a4a6b6adevice_5b94ca77-fab8-41b4-b286-311dee724813device_c3d8dcbf-d977-4d4d-8240-35b973ee00b9device_839371b0-1967-4435-910e-0d8e1c980850':
'VmDevice {vmId=8798d0da-a82c-4bcf-b41a-7e3fe1c613ef,
deviceId=839371b0-1967-4435-910e-0d8e1c980850, device=ide, type=CONTROLLER,
bootOrder=0, specParams={}, address={bus=0x00, domain=0x0000, type=pci,
slot=0x01, function=0x1}, managed=false, plugged=true, readOnly=false,
deviceAlias=ide0, customProperties={}}',
'device_99b583e9-9030-40af-bb41-55d62a4a6b6adevice_5b94ca77-fab8-41b4-b286-311dee724813':
'VmDevice {vmId=8798d0da-a82c-4bcf-b41a-7e3fe1c613ef,
deviceId=5b94ca77-fab8-41b4-b286-311dee724813, device=unix, type=CHANNEL,
bootOrder=0, specParams={}, address={port=2, bus=0, controller=0,
type=virtio-serial}, managed=false, plugged=true, readOnly=false,
deviceAlias=channel1, customProperties={}}'}, 'smp': '1',
'vmType': 'kvm',
'memSize': 1024, 'smpCoresPerSocket': '1', 'vmName':
'vm01', 'nice': '0', 'smartcardEnable': 'false',
'keyboardLayout': 'de',
'kvmEnable': 'true', 'pitReinjection': 'false',
'transparentHugePages':
'true', 'devices': [{'device': 'cirrus',
'specParams': {'vram': '65536'},
'type': 'video', 'deviceId':
'bf71f555-dc86-417b-9649-b06083b863b8',
'address': {'bus': '0x00', ' slot': '0x02', '
domain': '0x0000', ' type':
'pci', ' function': '0x0'}}, {'index': '2',
'iface': 'ide', 'address': {'
controller': '0', ' target': '0', 'unit':
'0', ' bus': '1', ' type':
'drive'}, 'specParams': {'path': ''}, 'readonly':
'true', 'deviceId':
'865f42a1-f64a-49cd-a706-76bc1bea8517', 'path': '',
'device': 'cdrom',
'shared': 'false', 'type': 'disk'}, {'index': 0,
'iface': 'virtio',
'format': 'raw', 'bootOrder': '1', 'poolID':
'5849b030-626e-47cb-ad90-3ce782d831b3', 'volumeID':
'd3011aef-3297-401c-88d7-65079e05dd4d', 'imageID':
'272b7bb5-38e6-41b3-9da4-4cc278873fbf', 'specParams': {},
'readonly':
'false', 'domainID': '8c8ad4f8-f187-410c-82a7-2beb79a51a30',
'optional':
'false', 'deviceId': '272b7bb5-38e6-41b3-9da4-4cc278873fbf',
'address':
{'bus': '0x00', ' slot': '0x05', ' domain':
'0x0000', ' type': 'pci', '
function': '0x0'}, 'device': 'disk', 'shared':
'false', 'propagateErrors':
'off', 'type': 'disk'}, {'nicModel': 'pv',
'macAddr': '52:54:00:6d:ce:c8',
'linkActive': 'true', 'network': 'VM', 'custom':
{}, 'filter':
'vdsm-no-mac-spoofing', 'specParams': {}, 'deviceId':
'78c714a7-9bc5-464b-85ae-328d29ba0b50', 'address': {'bus':
'0x00', ' slot':
'0x03', ' domain': '0x0000', ' type': 'pci',
' function': '0x0'}, 'device':
'bridge', 'type': 'interface'}], 'spiceSecureChannels':
'smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard',
'display': 'vnc'},) {} flowID [574ec4d2]
Thread-867485::INFO::2013-11-26 14:58:52,509::API::641::vds::(_getNetworkIp)
network None: using 0
Thread-867485::INFO::2013-11-26 14:58:52,509::clientIF::366::vds::(createVm)
vmContainerLock acquired by vm 8798d0da-a82c-4bcf-b41a-7e3fe1c613ef
Thread-867485::DEBUG::2013-11-26 14:58:52,515::clientIF::380::vds::(createVm)
Total desktops after creation of 8798d0da-a82c-4bcf-b41a-7e3fe1c613ef is 5
Thread-867486::DEBUG::2013-11-26
14:58:52,516::vm::2015::vm.Vm::(_startUnderlyingVm)
vmId=`8798d0da-a82c-4bcf-b41a-7e3fe1c613ef`::Start
Thread-867485::DEBUG::2013-11-26
14:58:52,516::BindingXMLRPC::986::vds::(wrapper) return vmCreate with
{'status': {'message': 'Done', 'code': 0},
'vmList': {'status':
'WaitForLaunch', 'acpiEnable': 'true', 'emulatedMachine':
'rhel6.4.0',
'tabletEnable': 'true', 'pid': '0',
'memGuaranteedSize': 512, 'timeOffset':
'1', 'keyboardLayout': 'de', 'displayPort': '-1',
'displaySecurePort': '-1',
'spiceSslCipherSuite': 'DEFAULT', 'cpuType': 'Nehalem',
'smp': '1',
'clientIp': '', 'nicModel': 'rtl8139,pv',
'smartcardEnable': 'false',
'kvmEnable': 'true', 'pitReinjection': 'false',
'vmId':
'8798d0da-a82c-4bcf-b41a-7e3fe1c613ef', 'transparentHugePages':
'true',
'devices': [{'device': 'cirrus', 'specParams':
{'vram': '65536'}, 'type':
'video', 'deviceId': 'bf71f555-dc86-417b-9649-b06083b863b8',
'address':
{'bus': '0x00', ' slot': '0x02', ' domain':
'0x0000', ' type': 'pci', '
function': '0x0'}}, {'index': '2', 'iface':
'ide', 'address': {'
controller': '0', ' target': '0', 'unit':
'0', ' bus': '1', ' type':
'drive'}, 'specParams': {'path': ''}, 'readonly':
'true', 'deviceId':
'865f42a1-f64a-49cd-a706-76bc1bea8517', 'path': '',
'device': 'cdrom',
'shared': 'false', 'type': 'disk'}, {'index': 0,
'iface': 'virtio',
'format': 'raw', 'bootOrder': '1', 'poolID':
'5849b030-626e-47cb-ad90-3ce782d831b3', 'volumeID':
'd3011aef-3297-401c-88d7-65079e05dd4d', 'imageID':
'272b7bb5-38e6-41b3-9da4-4cc278873fbf', 'specParams': {},
'readonly':
'false', 'domainID': '8c8ad4f8-f187-410c-82a7-2beb79a51a30',
'optional':
'false', 'deviceId': '272b7bb5-38e6-41b3-9da4-4cc278873fbf',
'address':
{'bus': '0x00', ' slot': '0x05', ' domain':
'0x0000', ' type': 'pci', '
function': '0x0'}, 'device': 'disk', 'shared':
'false', 'propagateErrors':
'off', 'type': 'disk'}, {'nicModel': 'pv',
'macAddr': '52:54:00:6d:ce:c8',
'linkActive': 'true', 'network': 'VM', 'custom':
{}, 'filter':
'vdsm-no-mac-spoofing', 'specParams': {}, 'deviceId':
'78c714a7-9bc5-464b-85ae-328d29ba0b50', 'address': {'bus':
'0x00', ' slot':
'0x03', ' domain': '0x0000', ' type': 'pci',
' function': '0x0'}, 'device':
'bridge', 'type': 'interface'}], 'custom':
{'device_99b583e9-9030-40af-bb41-55d62a4a6b6adevice_5b94ca77-fab8-41b4-b286-311dee724813device_c3d8dcbf-d977-4d4d-8240-35b973ee00b9':
'VmDevice {vmId=8798d0da-a82c-4bcf-b41a-7e3fe1c613ef,
deviceId=c3d8dcbf-d977-4d4d-8240-35b973ee00b9, device=scsi, type=CONTROLLER,
bootOrder=0, specParams={}, address={bus=0x00, domain=0x0000, type=pci,
slot=0x04, function=0x0}, managed=false, plugged=true, readOnly=false,
deviceAlias=scsi0, customProperties={}}',
'device_99b583e9-9030-40af-bb41-55d62a4a6b6a': 'VmDevice
{vmId=8798d0da-a82c-4bcf-b41a-7e3fe1c613ef,
deviceId=99b583e9-9030-40af-bb41-55d62a4a6b6a, device=unix, type=CHANNEL,
bootOrder=0, specParams={}, address={port=1, bus=0, controller=0,
type=virtio-serial}, managed=false, plugged=true, readOnly=false,
deviceAlias=channel0, customProperties={}}',
'device_99b583e9-9030-40af-bb41-55d62a4a6b6adevice_5b94ca77-fab8-41b4-b286-311dee724813device_c3d8dcbf-d977-4d4d-8240-35b973ee00b9device_839371b0-1967-4435-910e-0d8e1c980850device_920282ca-79c2-4abf-b1f2-7425f16f7820':
'VmDevice {vmId=8798d0da-a82c-4bcf-b41a-7e3fe1c613ef,
deviceId=920282ca-79c2-4abf-b1f2-7425f16f7820, device=virtio-serial,
type=CONTROLLER, bootOrder=0, specParams={}, address={bus=0x00,
domain=0x0000, type=pci, slot=0x06, function=0x0}, managed=false,
plugged=true, readOnly=false, deviceAlias=virtio-serial0,
customProperties={}}',
'device_99b583e9-9030-40af-bb41-55d62a4a6b6adevice_5b94ca77-fab8-41b4-b286-311dee724813device_c3d8dcbf-d977-4d4d-8240-35b973ee00b9device_839371b0-1967-4435-910e-0d8e1c980850':
'VmDevice {vmId=8798d0da-a82c-4bcf-b41a-7e3fe1c613ef,
deviceId=839371b0-1967-4435-910e-0d8e1c980850, device=ide, type=CONTROLLER,
bootOrder=0, specParams={}, address={bus=0x00, domain=0x0000, type=pci,
slot=0x01, function=0x1}, managed=false, plugged=true, readOnly=false,
deviceAlias=ide0, customProperties={}}',
'device_99b583e9-9030-40af-bb41-55d62a4a6b6adevice_5b94ca77-fab8-41b4-b286-311dee724813':
'VmDevice {vmId=8798d0da-a82c-4bcf-b41a-7e3fe1c613ef,
deviceId=5b94ca77-fab8-41b4-b286-311dee724813, device=unix, type=CHANNEL,
bootOrder=0, specParams={}, address={port=2, bus=0, controller=0,
type=virtio-serial}, managed=false, plugged=true, readOnly=false,
deviceAlias=channel1, customProperties={}}'}, 'vmType': 'kvm',
'memSize':
1024, 'displayIp': '0', 'spiceSecureChannels':
'smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard',
'smpCoresPerSocket': '1', 'vmName':
'vm01', 'display': 'vnc', 'nice': '0'}}
Thread-867486::DEBUG::2013-11-26
14:58:52,519::vm::2019::vm.Vm::(_startUnderlyingVm)
vmId=`8798d0da-a82c-4bcf-b41a-7e3fe1c613ef`::_ongoingCreations acquired
Thread-867486::INFO::2013-11-26 14:58:52,522::vm::2815::vm.Vm::(_run)
vmId=`8798d0da-a82c-4bcf-b41a-7e3fe1c613ef`::VM wrapper has started
Thread-867486::DEBUG::2013-11-26
14:58:52,527::task::579::TaskManager.Task::(_updateState)
Task=`e64eb271-e389-4057-81f7-1148059464d7`::moving from state init -> state
preparing
Thread-867486::INFO::2013-11-26
14:58:52,530::logUtils::44::dispatcher::(wrapper) Run and protect:
getVolumeSize(sdUUID='8c8ad4f8-f187-410c-82a7-2beb79a51a30',
spUUID='5849b030-626e-47cb-ad90-3ce782d831b3',
imgUUID='272b7bb5-38e6-41b3-9da4-4cc278873fbf',
volUUID='d3011aef-3297-401c-88d7-65079e05dd4d', options=None)
Thread-867486::DEBUG::2013-11-26
14:58:52,534::lvm::415::OperationMutex::(_reloadlvs) Operation 'lvm reload
operation' got the operation mutex
Thread-867486::DEBUG::2013-11-26
14:58:52,539::lvm::311::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n
/sbin/lvm lvs --config " devices { preferred_names =
[\\"^/dev/mapper/\\"]
ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3
filter = [
\'a|/dev/mapper/360014051fd69751de087d46f1da5aadb|/dev/mapper/360014056ce3d140de6a5d4fffd9218da|/dev/mapper/360014056db0fc0fdcda7d4a27da043d5|/dev/mapper/36001405917dfc0dd0809d41cfd86c9d4|/dev/mapper/3600508b1001cd6f84303d050b8fb5a80|\',
\'r|.*|\' ] } global { locking_type=1 prioritise_write_locks=1
wait_for_locks=1 } backup { retain_min = 50 retain_days = 0 } " --noheadings
--units b --nosuffix --separator | -o
uuid,name,vg_name,attr,size,seg_start_pe,devices,tags
8c8ad4f8-f187-410c-82a7-2beb79a51a30' (cwd None)
Thread-867486::DEBUG::2013-11-26
14:58:52,588::lvm::311::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '';
<rc>
= 0
Thread-867486::DEBUG::2013-11-26
14:58:52,623::lvm::448::OperationMutex::(_reloadlvs) Operation 'lvm reload
operation' released the operation mutex
Thread-867486::INFO::2013-11-26
14:58:52,623::logUtils::47::dispatcher::(wrapper) Run and protect:
getVolumeSize, Return response: {'truesize': '42949672960',
'apparentsize':
'42949672960'}
Thread-867486::DEBUG::2013-11-26
14:58:52,624::task::1168::TaskManager.Task::(prepare)
Task=`e64eb271-e389-4057-81f7-1148059464d7`::finished: {'truesize':
'42949672960', 'apparentsize': '42949672960'}
Thread-867486::DEBUG::2013-11-26
14:58:52,624::task::579::TaskManager.Task::(_updateState)
Task=`e64eb271-e389-4057-81f7-1148059464d7`::moving from state preparing ->
state finished
Thread-867486::DEBUG::2013-11-26
14:58:52,624::resourceManager::939::ResourceManager.Owner::(releaseAll)
Owner.releaseAll requests {} resources {}
Thread-867486::DEBUG::2013-11-26
14:58:52,625::resourceManager::976::ResourceManager.Owner::(cancelAll)
Owner.cancelAll requests {}
Thread-867486::DEBUG::2013-11-26
14:58:52,625::task::974::TaskManager.Task::(_decref)
Task=`e64eb271-e389-4057-81f7-1148059464d7`::ref 0 aborting False
Thread-867486::INFO::2013-11-26
14:58:52,625::clientIF::325::vds::(prepareVolumePath) prepared volume path:
Thread-867486::DEBUG::2013-11-26
14:58:52,626::task::579::TaskManager.Task::(_updateState)
Task=`e0d9071f-a343-400e-865d-81656dd8862b`::moving from state init -> state
preparing
Thread-867486::INFO::2013-11-26
14:58:52,626::logUtils::44::dispatcher::(wrapper) Run and protect:
prepareImage(sdUUID='8c8ad4f8-f187-410c-82a7-2beb79a51a30',
spUUID='5849b030-626e-47cb-ad90-3ce782d831b3',
imgUUID='272b7bb5-38e6-41b3-9da4-4cc278873fbf',
volUUID='d3011aef-3297-401c-88d7-65079e05dd4d')
Thread-867486::DEBUG::2013-11-26
14:58:52,627::resourceManager::197::ResourceManager.Request::(__init__)
ResName=`Storage.8c8ad4f8-f187-410c-82a7-2beb79a51a30`ReqID=`664dc122-58c1-49d1-a03e-faa2182f42da`::Request
was made in '/usr/share/vdsm/storage/hsm.py' line '3240' at
'prepareImage'
Thread-867486::DEBUG::2013-11-26
14:58:52,627::resourceManager::541::ResourceManager::(registerResource)
Trying to register resource 'Storage.8c8ad4f8-f187-410c-82a7-2beb79a51a30'
for lock type 'shared'
Thread-867486::DEBUG::2013-11-26
14:58:52,628::resourceManager::600::ResourceManager::(registerResource)
Resource 'Storage.8c8ad4f8-f187-410c-82a7-2beb79a51a30' is free. Now locking
as 'shared' (1 active user)
Thread-867486::DEBUG::2013-11-26
14:58:52,628::resourceManager::237::ResourceManager.Request::(grant)
ResName=`Storage.8c8ad4f8-f187-410c-82a7-2beb79a51a30`ReqID=`664dc122-58c1-49d1-a03e-faa2182f42da`::Granted
request
Thread-867486::DEBUG::2013-11-26
14:58:52,629::task::811::TaskManager.Task::(resourceAcquired)
Task=`e0d9071f-a343-400e-865d-81656dd8862b`::_resourcesAcquired:
Storage.8c8ad4f8-f187-410c-82a7-2beb79a51a30 (shared)
Thread-867486::DEBUG::2013-11-26
14:58:52,629::task::974::TaskManager.Task::(_decref)
Task=`e0d9071f-a343-400e-865d-81656dd8862b`::ref 1 aborting False
Thread-867486::DEBUG::2013-11-26
14:58:52,635::blockVolume::588::Storage.Misc.excCmd::(getMetadata) '/bin/dd
iflag=direct skip=23 bs=512
if=/dev/8c8ad4f8-f187-410c-82a7-2beb79a51a30/metadata count=1' (cwd None)
Thread-867486::DEBUG::2013-11-26
14:58:52,644::blockVolume::588::Storage.Misc.excCmd::(getMetadata) SUCCESS:
<err> = '1+0 records in\n1+0 records out\n512 bytes (512 B) copied,
0.000281928 s, 1.8 MB/s\n'; <rc> = 0
Thread-867486::DEBUG::2013-11-26
14:58:52,644::misc::288::Storage.Misc::(validateDDBytes) err: ['1+0 records
in', '1+0 records out', '512 bytes (512 B) copied, 0.000281928 s, 1.8
MB/s'], size: 512
Thread-867486::INFO::2013-11-26
14:58:52,645::image::215::Storage.Image::(getChain)
sdUUID=8c8ad4f8-f187-410c-82a7-2beb79a51a30
imgUUID=272b7bb5-38e6-41b3-9da4-4cc278873fbf
chain=[<storage.blockVolume.BlockVolume object at 0x14f6ad0>]
Thread-867486::DEBUG::2013-11-26
14:58:52,646::lvm::311::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n
/sbin/lvm lvchange --config " devices { preferred_names =
[\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0
disable_after_error_count=3 filter = [
\'a|/dev/mapper/360014051fd69751de087d46f1da5aadb|/dev/mapper/360014056ce3d140de6a5d4fffd9218da|/dev/mapper/360014056db0fc0fdcda7d4a27da043d5|/dev/mapper/36001405917dfc0dd0809d41cfd86c9d4|/dev/mapper/3600508b1001cd6f84303d050b8fb5a80|\',
\'r|.*|\' ] } global { locking_type=1 prioritise_write_locks=1
wait_for_locks=1 } backup { retain_min = 50 retain_days = 0 } " --autobackup
n --available y
8c8ad4f8-f187-410c-82a7-2beb79a51a30/d3011aef-3297-401c-88d7-65079e05dd4d'
(cwd None)
Thread-867486::DEBUG::2013-11-26
14:58:52,942::lvm::311::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '';
<rc>
= 0
Thread-867486::DEBUG::2013-11-26
14:58:52,943::lvm::499::OperationMutex::(_invalidatelvs) Operation 'lvm
invalidate operation' got the operation mutex
Thread-867486::DEBUG::2013-11-26
14:58:52,943::lvm::511::OperationMutex::(_invalidatelvs) Operation 'lvm
invalidate operation' released the operation mutex
Thread-867486::DEBUG::2013-11-26
14:58:52,943::lvm::415::OperationMutex::(_reloadlvs) Operation 'lvm reload
operation' got the operation mutex
Thread-867486::DEBUG::2013-11-26
14:58:52,944::lvm::311::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n
/sbin/lvm lvs --config " devices { preferred_names =
[\\"^/dev/mapper/\\"]
ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3
filter = [
\'a|/dev/mapper/360014051fd69751de087d46f1da5aadb|/dev/mapper/360014056ce3d140de6a5d4fffd9218da|/dev/mapper/360014056db0fc0fdcda7d4a27da043d5|/dev/mapper/36001405917dfc0dd0809d41cfd86c9d4|/dev/mapper/3600508b1001cd6f84303d050b8fb5a80|\',
\'r|.*|\' ] } global { locking_type=1 prioritise_write_locks=1
wait_for_locks=1 } backup { retain_min = 50 retain_days = 0 } " --noheadings
--units b --nosuffix --separator | -o
uuid,name,vg_name,attr,size,seg_start_pe,devices,tags
8c8ad4f8-f187-410c-82a7-2beb79a51a30' (cwd None)
Thread-867486::DEBUG::2013-11-26
14:58:53,242::lvm::311::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '';
<rc>
= 0
Thread-867486::DEBUG::2013-11-26
14:58:53,277::lvm::448::OperationMutex::(_reloadlvs) Operation 'lvm reload
operation' released the operation mutex
Thread-867486::DEBUG::2013-11-26
14:58:53,283::blockVolume::588::Storage.Misc.excCmd::(getMetadata) '/bin/dd
iflag=direct skip=23 bs=512
if=/dev/8c8ad4f8-f187-410c-82a7-2beb79a51a30/metadata count=1' (cwd None)
Thread-867486::DEBUG::2013-11-26
14:58:53,292::blockVolume::588::Storage.Misc.excCmd::(getMetadata) SUCCESS:
<err> = '1+0 records in\n1+0 records out\n512 bytes (512 B) copied,
0.000298328 s, 1.7 MB/s\n'; <rc> = 0
Thread-867486::DEBUG::2013-11-26
14:58:53,292::misc::288::Storage.Misc::(validateDDBytes) err: ['1+0 records
in', '1+0 records out', '512 bytes (512 B) copied, 0.000298328 s, 1.7
MB/s'], size: 512
Thread-867486::INFO::2013-11-26
14:58:53,293::logUtils::47::dispatcher::(wrapper) Run and protect:
prepareImage, Return response: {'info': {'path':
'/rhev/data-center/5849b030-626e-47cb-ad90-3ce782d831b3/8c8ad4f8-f187-410c-82a7-2beb79a51a30/images/272b7bb5-38e6-41b3-9da4-4cc278873fbf/d3011aef-3297-401c-88d7-65079e05dd4d',
'volType': 'path'}, 'path':
'/rhev/data-center/5849b030-626e-47cb-ad90-3ce782d831b3/8c8ad4f8-f187-410c-82a7-2beb79a51a30/images/272b7bb5-38e6-41b3-9da4-4cc278873fbf/d3011aef-3297-401c-88d7-65079e05dd4d',
'chain': [{'path':
'/rhev/data-center/5849b030-626e-47cb-ad90-3ce782d831b3/8c8ad4f8-f187-410c-82a7-2beb79a51a30/images/272b7bb5-38e6-41b3-9da4-4cc278873fbf/d3011aef-3297-401c-88d7-65079e05dd4d',
'domainID': '8c8ad4f8-f187-410c-82a7-2beb79a51a30', 'vmVolInfo':
{'path':
'/rhev/data-center/5849b030-626e-47cb-ad90-3ce782d831b3/8c8ad4f8-f187-410c-82a7-2beb79a51a30/images/272b7bb5-38e6-41b3-9da4-4cc278873fbf/d3011aef-3297-401c-88d7-65079e05dd4d',
'volType': 'path'}, 'volumeID':
'd3011aef-3297-401c-88d7-65079e05dd4d',
'imageID': '272b7bb5-38e6-41b3-9da4-4cc278873fbf'}]}
Thread-867486::DEBUG::2013-11-26
14:58:53,293::task::1168::TaskManager.Task::(prepare)
Task=`e0d9071f-a343-400e-865d-81656dd8862b`::finished: {'info': {'path':
'/rhev/data-center/5849b030-626e-47cb-ad90-3ce782d831b3/8c8ad4f8-f187-410c-82a7-2beb79a51a30/images/272b7bb5-38e6-41b3-9da4-4cc278873fbf/d3011aef-3297-401c-88d7-65079e05dd4d',
'volType': 'path'}, 'path':
'/rhev/data-center/5849b030-626e-47cb-ad90-3ce782d831b3/8c8ad4f8-f187-410c-82a7-2beb79a51a30/images/272b7bb5-38e6-41b3-9da4-4cc278873fbf/d3011aef-3297-401c-88d7-65079e05dd4d',
'chain': [{'path':
'/rhev/data-center/5849b030-626e-47cb-ad90-3ce782d831b3/8c8ad4f8-f187-410c-82a7-2beb79a51a30/images/272b7bb5-38e6-41b3-9da4-4cc278873fbf/d3011aef-3297-401c-88d7-65079e05dd4d',
'domainID': '8c8ad4f8-f187-410c-82a7-2beb79a51a30', 'vmVolInfo':
{'path':
'/rhev/data-center/5849b030-626e-47cb-ad90-3ce782d831b3/8c8ad4f8-f187-410c-82a7-2beb79a51a30/images/272b7bb5-38e6-41b3-9da4-4cc278873fbf/d3011aef-3297-401c-88d7-65079e05dd4d',
'volType': 'path'}, 'volumeID':
'd3011aef-3297-401c-88d7-65079e05dd4d',
'imageID': '272b7bb5-38e6-41b3-9da4-4cc278873fbf'}]}
Thread-867486::DEBUG::2013-11-26
14:58:53,293::task::579::TaskManager.Task::(_updateState)
Task=`e0d9071f-a343-400e-865d-81656dd8862b`::moving from state preparing ->
state finished
Thread-867486::DEBUG::2013-11-26
14:58:53,294::resourceManager::939::ResourceManager.Owner::(releaseAll)
Owner.releaseAll requests {} resources
{'Storage.8c8ad4f8-f187-410c-82a7-2beb79a51a30': < ResourceRef
'Storage.8c8ad4f8-f187-410c-82a7-2beb79a51a30', isValid: 'True' obj:
'None'>}
Thread-867486::DEBUG::2013-11-26
14:58:53,294::resourceManager::976::ResourceManager.Owner::(cancelAll)
Owner.cancelAll requests {}
Thread-867486::DEBUG::2013-11-26
14:58:53,294::resourceManager::615::ResourceManager::(releaseResource)
Trying to release resource 'Storage.8c8ad4f8-f187-410c-82a7-2beb79a51a30'
Thread-867486::DEBUG::2013-11-26
14:58:53,295::resourceManager::634::ResourceManager::(releaseResource)
Released resource 'Storage.8c8ad4f8-f187-410c-82a7-2beb79a51a30' (0 active
users)
Thread-867486::DEBUG::2013-11-26
14:58:53,295::resourceManager::640::ResourceManager::(releaseResource)
Resource 'Storage.8c8ad4f8-f187-410c-82a7-2beb79a51a30' is free, finding out
if anyone is waiting for it.
Thread-867486::DEBUG::2013-11-26
14:58:53,295::resourceManager::648::ResourceManager::(releaseResource) No
one is waiting for resource 'Storage.8c8ad4f8-f187-410c-82a7-2beb79a51a30',
Clearing records.
Thread-867486::DEBUG::2013-11-26
14:58:53,296::task::974::TaskManager.Task::(_decref)
Task=`e0d9071f-a343-400e-865d-81656dd8862b`::ref 0 aborting False
Thread-867486::INFO::2013-11-26
14:58:53,296::clientIF::325::vds::(prepareVolumePath) prepared volume path:
/rhev/data-center/5849b030-626e-47cb-ad90-3ce782d831b3/8c8ad4f8-f187-410c-82a7-2beb79a51a30/images/272b7bb5-38e6-41b3-9da4-4cc278873fbf/d3011aef-3297-401c-88d7-65079e05dd4d
Thread-867486::DEBUG::2013-11-26 14:58:53,318::utils::486::root::(execCmd)
'/usr/libexec/vdsm/hooks/before_vm_start/50_smbios' (cwd None)
Thread-867486::DEBUG::2013-11-26 14:58:53,400::utils::505::root::(execCmd)
SUCCESS: <err> = ''; <rc> = 0
Thread-867486::INFO::2013-11-26 14:58:53,401::hooks::88::root::(_runHooksDir)
Thread-867486::DEBUG::2013-11-26 14:58:53,401::vm::2872::vm.Vm::(_run)
vmId=`8798d0da-a82c-4bcf-b41a-7e3fe1c613ef`::<?xml version="1.0"
encoding="utf-8"?>
<domain type="kvm">
<name>vm01</name>
<uuid>8798d0da-a82c-4bcf-b41a-7e3fe1c613ef</uuid>
<memory>1048576</memory>
<currentMemory>1048576</currentMemory>
<vcpu>1</vcpu>
<memtune>
<min_guarantee>524288</min_guarantee>
</memtune>
<devices>
<channel type="unix">
<target name="com.redhat.rhevm.vdsm" type="virtio"/>
<source mode="bind"
path="/var/lib/libvirt/qemu/channels/8798d0da-a82c-4bcf-b41a-7e3fe1c613ef.com.redhat.rhevm.vdsm"/>
</channel>
<channel type="unix">
<target name="org.qemu.guest_agent.0" type="virtio"/>
<source mode="bind"
path="/var/lib/libvirt/qemu/channels/8798d0da-a82c-4bcf-b41a-7e3fe1c613ef.org.qemu.guest_agent.0"/>
</channel>
<input bus="usb" type="tablet"/>
<graphics autoport="yes" keymap="de" listen="0"
passwd="*****"
passwdValidTo="1970-01-01T00:00:01" port="-1"
type="vnc"/>
<video>
<address bus="0x00" domain="0x0000" function="0x0"
slot="0x02" type="pci"/>
<model heads="1" type="cirrus" vram="65536"/>
</video>
<interface type="bridge">
<address bus="0x00" domain="0x0000" function="0x0"
slot="0x03" type="pci"/>
<mac address="52:54:00:6d:ce:c8"/>
<model type="virtio"/>
<source bridge="VM"/>
<filterref filter="vdsm-no-mac-spoofing"/>
<link state="up"/>
</interface>
<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/>
</disk>
<disk device="disk" snapshot="no" type="block">
<address bus="0x00" domain="0x0000" function="0x0"
slot="0x05" type="pci"/>
<source
dev="/rhev/data-center/5849b030-626e-47cb-ad90-3ce782d831b3/8c8ad4f8-f187-410c-82a7-2beb79a51a30/images/272b7bb5-38e6-41b3-9da4-4cc278873fbf/d3011aef-3297-401c-88d7-65079e05dd4d"/>
<target bus="virtio" dev="vda"/>
<serial>272b7bb5-38e6-41b3-9da4-4cc278873fbf</serial>
<boot order="1"/>
<driver cache="none" error_policy="stop" io="native"
name="qemu" type="raw"/>
</disk>
<memballoon model="none"/>
</devices>
<os>
<type arch="x86_64" machine="rhel6.4.0">hvm</type>
<smbios mode="sysinfo"/>
</os>
<sysinfo type="smbios">
<system>
<entry name="manufacturer">oVirt</entry>
<entry name="product">oVirt Node</entry>
<entry name="version">6-4.el6.centos.10</entry>
<entry name="serial">32393735-3933-5A43-4A32-34333046564B</entry>
<entry name="uuid">8798d0da-a82c-4bcf-b41a-7e3fe1c613ef</entry>
</system>
</sysinfo>
<clock adjustment="1" offset="variable">
<timer name="rtc" tickpolicy="catchup"/>
</clock>
<features>
<acpi/>
</features>
<cpu match="exact">
<model>Nehalem</model>
<topology cores="1" sockets="1" threads="1"/>
</cpu>
</domain>
Thread-166407::DEBUG::2013-11-26
14:58:53,588::blockSD::594::Storage.Misc.excCmd::(getReadDelay) '/bin/dd
iflag=direct if=/dev/8c8ad4f8-f187-410c-82a7-2beb79a51a30/metadata bs=4096
count=1' (cwd None)
Thread-166407::DEBUG::2013-11-26
14:58:53,599::blockSD::594::Storage.Misc.excCmd::(getReadDelay) SUCCESS:
<err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied,
0.000345562 s, 11.9 MB/s\n'; <rc> = 0
Thread-24::DEBUG::2013-11-26
14:58:53,791::fileSD::238::Storage.Misc.excCmd::(getReadDelay) '/bin/dd
iflag=direct
if=/rhev/data-center/mnt/engine.privat.com:_export_VMs/48055e27-f1ca-466a-8a2c-e191c34f0226/dom_md/metadata
bs=4096 count=1' (cwd None)
Thread-24::DEBUG::2013-11-26
14:58:53,801::fileSD::238::Storage.Misc.excCmd::(getReadDelay) SUCCESS:
<err> = '0+1 records in\n0+1 records out\n349 bytes (349 B) copied,
0.000683955 s, 510 kB/s\n'; <rc> = 0
libvirtEventLoop::DEBUG::2013-11-26
14:58:54,094::vm::4724::vm.Vm::(_onLibvirtLifecycleEvent)
vmId=`8798d0da-a82c-4bcf-b41a-7e3fe1c613ef`::event Started detail 0 opaque
None
Thread-867486::DEBUG::2013-11-26 14:58:54,248::sampling::285::vm.Vm::(start)
vmId=`8798d0da-a82c-4bcf-b41a-7e3fe1c613ef`::Start statistics collection
Thread-867488::DEBUG::2013-11-26 14:58:54,249::sampling::314::vm.Vm::(run)
vmId=`8798d0da-a82c-4bcf-b41a-7e3fe1c613ef`::Stats thread started
Thread-867486::DEBUG::2013-11-26
14:58:54,251::vmChannels::194::vds::(register) Add fileno 51 to listener's
channels.
Thread-867488::DEBUG::2013-11-26
14:58:54,253::task::579::TaskManager.Task::(_updateState)
Task=`c5c6d816-7de8-4ab5-a5fa-a3fba225d797`::moving from state init -> state
preparing
Thread-867488::INFO::2013-11-26
14:58:54,253::logUtils::44::dispatcher::(wrapper) Run and protect:
getVolumeSize(sdUUID='8c8ad4f8-f187-410c-82a7-2beb79a51a30',
spUUID='5849b030-626e-47cb-ad90-3ce782d831b3',
imgUUID='272b7bb5-38e6-41b3-9da4-4cc278873fbf',
volUUID='d3011aef-3297-401c-88d7-65079e05dd4d', options=None)
Thread-867486::WARNING::2013-11-26
14:58:54,253::vm::3326::vm.Vm::(_readPauseCode)
vmId=`8798d0da-a82c-4bcf-b41a-7e3fe1c613ef`::_readPauseCode unsupported by
libvirt vm
Thread-867488::INFO::2013-11-26
14:58:54,255::logUtils::47::dispatcher::(wrapper) Run and protect:
getVolumeSize, Return response: {'truesize': '42949672960',
'apparentsize':
'42949672960'}
Thread-867488::DEBUG::2013-11-26
14:58:54,256::task::1168::TaskManager.Task::(prepare)
Task=`c5c6d816-7de8-4ab5-a5fa-a3fba225d797`::finished: {'truesize':
'42949672960', 'apparentsize': '42949672960'}
Thread-867488::DEBUG::2013-11-26
14:58:54,256::task::579::TaskManager.Task::(_updateState)
Task=`c5c6d816-7de8-4ab5-a5fa-a3fba225d797`::moving from state preparing ->
state finished
Thread-867488::DEBUG::2013-11-26
14:58:54,256::resourceManager::939::ResourceManager.Owner::(releaseAll)
Owner.releaseAll requests {} resources {}
Thread-867488::DEBUG::2013-11-26
14:58:54,257::resourceManager::976::ResourceManager.Owner::(cancelAll)
Owner.cancelAll requests {}
Thread-867488::DEBUG::2013-11-26
14:58:54,257::task::974::TaskManager.Task::(_decref)
Task=`c5c6d816-7de8-4ab5-a5fa-a3fba225d797`::ref 0 aborting False
Thread-867486::DEBUG::2013-11-26
14:58:54,263::vm::2036::vm.Vm::(_startUnderlyingVm)
vmId=`8798d0da-a82c-4bcf-b41a-7e3fe1c613ef`::_ongoingCreations released
VM Channels Listener::DEBUG::2013-11-26
14:58:54,694::vmChannels::102::vds::(_do_add_channels) fileno 51 was added
to unconnected channels.
VM Channels Listener::DEBUG::2013-11-26
14:58:54,694::vmChannels::128::vds::(_handle_unconnected) Trying to connect
fileno 51.
VM Channels Listener::DEBUG::2013-11-26
14:58:54,695::guestIF::147::vm.Vm::(_connect)
vmId=`8798d0da-a82c-4bcf-b41a-7e3fe1c613ef`::Attempting connection to
/var/lib/libvirt/qemu/channels/8798d0da-a82c-4bcf-b41a-7e3fe1c613ef.com.redhat.rhevm.vdsm
VM Channels Listener::DEBUG::2013-11-26
14:58:54,695::guestIF::150::vm.Vm::(_connect)
vmId=`8798d0da-a82c-4bcf-b41a-7e3fe1c613ef`::Connected to
/var/lib/libvirt/qemu/channels/8798d0da-a82c-4bcf-b41a-7e3fe1c613ef.com.redhat.rhevm.vdsm
VM Channels Listener::DEBUG::2013-11-26
14:58:54,695::vmChannels::144::vds::(_handle_unconnected) Connecting to
fileno 51 succeeded.
Thread-867490::DEBUG::2013-11-26
14:58:55,170::BindingXMLRPC::979::vds::(wrapper) client [192.168.1.29]::call
vmGetStats with ('8798d0da-a82c-4bcf-b41a-7e3fe1c613ef',) {}
Thread-867490::DEBUG::2013-11-26 14:58:55,170::vm::579::vm.Vm::(_getCpuStats)
vmId=`8798d0da-a82c-4bcf-b41a-7e3fe1c613ef`::CPU stats not available:
'NoneType' object is unsubscriptable
Thread-867490::DEBUG::2013-11-26
14:58:55,170::vm::613::vm.Vm::(_getNetworkStats)
vmId=`8798d0da-a82c-4bcf-b41a-7e3fe1c613ef`::Network stats not available
_______________________________________________
Users mailing list
Users(a)ovirt.org
http://lists.ovirt.org/mailman/listinfo/users
4043
days inactive
4043
days old
1 comments
2 participants
participants (2)
-
Gilad Chaplik -
Hans-Joachim