[Users] Problem starting VM in oVirt 3.3.1-2

Wed Nov 27 11:46:17 EST 2013

----- Original Message -----
> From: "Hans-Joachim" <rni at chef.net>
> To: users at 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 at ovirt.org
> http://lists.ovirt.org/mailman/listinfo/users
> 