Re: [Users] Problem starting VM in oVirt 3.3.1-2

From: "Hans-Joachim" <rni(a)chef.net&gt; 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.

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