Hi All,
In my ovirt live 1.1 system (ran as-is, done no alterations to the system once
"installed"),
after attempting to run the default 'local_vm' VM, it is getting stuck on 'Wait
For Launch'.
I tried running the ovirt live 1.1 system for ~5 times, only in one of these
times the VM
has actually moved to the Powering Up / Up state when attempting to run it.
Any ideas?
[attached engine.log, vdsm.log]
Many thanks in advance!
----
Regards,
Einav
Thread-125::DEBUG::2013-11-03 11:52:25,709::BindingXMLRPC::979::vds::(wrapper) client [10.0.0.1]::call vmCreate with ({'custom': {}, 'keyboardLayout': 'en-us', 'kvmEnable': 'true', 'acpiEnable': 'true', 'emulatedMachine': 'rhel6.4.0', 'cpuType': 'Penryn', 'vmId': '1f0a2763-5c40-4fa3-a51c-ed98276b8e6d', 'devices': [{'device': 'qxl', 'specParams': {'vram': '65536'}, 'type': 'video', 'deviceId': '50623be3-019e-4276-a1df-2b1cdb933e69'}, {'index': '2', 'iface': 'ide', 'bootOrder': '1', 'specParams': {'path': ''}, 'readonly': 'true', 'deviceId': '49494a9a-1f6c-41aa-a9f5-189492c2bfdb', 'path': '', 'device': 'cdrom', 'shared': 'false', 'type': 'disk'}, {'index': 0, 'iface': 'virtio', 'format': 'cow', 'type': 'disk', 'volumeID': 'bcabc2ba-b7e1-47f9-9098-bbe19b096ad5', 'imageID': 'a544c2c3-cf3a-42c7-8e20-371344ad22da', 'specParams': {}, 'readonly': 'false', 'domainID': '5b5e5322-df22-4516-860b-361f00c46233', 'deviceId': 'a544c2c3-cf3a-42c7-8e20-371344ad22da', 'poolID': '9b476274-7c1c-4762-8cb4-699c2729b152', 'device': 'disk', 'shared': 'false', 'propagateErrors': 'off', 'optional': 'false'}, {'device': 'scsi', 'model': 'virtio-scsi', 'type': 'controller'}, {'nicModel': 'pv', 'macAddr': '00:1a:4a:7d:ea:72', 'linkActive': 'true', 'network': 'ovirtmgmt', 'custom': {}, 'filter': 'vdsm-no-mac-spoofing', 'specParams': {}, 'deviceId': '2bc8c2d5-2dd5-4ed6-8626-fadefdbd3fe2', 'device': 'bridge', 'type': 'interface'}, {'device': 'ich6', 'specParams': {}, 'type': 'sound', 'deviceId': '6ca24c83-e175-4a24-9803-0dba03d8cb3f'}, {'device': 'memballoon', 'specParams': {'model': 'virtio'}, 'type': 'balloon', 'deviceId': '46b9f702-4b90-4b04-85e3-6e37e9b138e9'}], 'smp': '1', 'vmType': 'kvm', 'smartcardEnable': 'false', 'timeOffset': '0', 'memSize': 1024, 'spiceSslCipherSuite': 'DEFAULT', 'smpCoresPerSocket': '1', 'spiceSecureChannels': 'smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard', 'memGuaranteedSize': 1024, 'vmName': 'local_vm', 'display': 'qxl', 'transparentHugePages': 'true', 'nice': '0'},) {} flowID [1acbcb1d]
Thread-125::INFO::2013-11-03 11:52:25,716::API::641::vds::(_getNetworkIp) network None: using 0
Thread-125::INFO::2013-11-03 11:52:25,717::clientIF::366::vds::(createVm) vmContainerLock acquired by vm 1f0a2763-5c40-4fa3-a51c-ed98276b8e6d
Thread-126::DEBUG::2013-11-03 11:52:25,720::vm::2015::vm.Vm::(_startUnderlyingVm) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Start
Thread-126::DEBUG::2013-11-03 11:52:25,720::vm::2019::vm.Vm::(_startUnderlyingVm) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::_ongoingCreations acquired
Thread-126::INFO::2013-11-03 11:52:25,720::vm::2815::vm.Vm::(_run) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::VM wrapper has started
Thread-126::DEBUG::2013-11-03 11:52:25,721::task::579::TaskManager.Task::(_updateState) Task=`4d86c7fa-9a7b-4c4f-aca9-2ef08da5e287`::moving from state init -> state preparing
Thread-126::INFO::2013-11-03 11:52:25,721::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='5b5e5322-df22-4516-860b-361f00c46233', spUUID='9b476274-7c1c-4762-8cb4-699c2729b152', imgUUID='a544c2c3-cf3a-42c7-8e20-371344ad22da', volUUID='bcabc2ba-b7e1-47f9-9098-bbe19b096ad5', options=None)
Thread-126::DEBUG::2013-11-03 11:52:25,723::fileVolume::520::Storage.Volume::(validateVolumePath) validate path for bcabc2ba-b7e1-47f9-9098-bbe19b096ad5
Thread-126::INFO::2013-11-03 11:52:25,725::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '139264', 'apparentsize': '262144'}
Thread-126::DEBUG::2013-11-03 11:52:25,725::task::1168::TaskManager.Task::(prepare) Task=`4d86c7fa-9a7b-4c4f-aca9-2ef08da5e287`::finished: {'truesize': '139264', 'apparentsize': '262144'}
Thread-126::DEBUG::2013-11-03 11:52:25,725::task::579::TaskManager.Task::(_updateState) Task=`4d86c7fa-9a7b-4c4f-aca9-2ef08da5e287`::moving from state preparing -> state finished
Thread-126::DEBUG::2013-11-03 11:52:25,726::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-126::DEBUG::2013-11-03 11:52:25,726::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-126::DEBUG::2013-11-03 11:52:25,726::task::974::TaskManager.Task::(_decref) Task=`4d86c7fa-9a7b-4c4f-aca9-2ef08da5e287`::ref 0 aborting False
Thread-126::INFO::2013-11-03 11:52:25,726::clientIF::325::vds::(prepareVolumePath) prepared volume path:
Thread-126::DEBUG::2013-11-03 11:52:25,727::task::579::TaskManager.Task::(_updateState) Task=`28cb4bfb-20e0-4f02-bbdf-826571b98217`::moving from state init -> state preparing
Thread-126::INFO::2013-11-03 11:52:25,727::logUtils::44::dispatcher::(wrapper) Run and protect: prepareImage(sdUUID='5b5e5322-df22-4516-860b-361f00c46233', spUUID='9b476274-7c1c-4762-8cb4-699c2729b152', imgUUID='a544c2c3-cf3a-42c7-8e20-371344ad22da', volUUID='bcabc2ba-b7e1-47f9-9098-bbe19b096ad5')
Thread-126::DEBUG::2013-11-03 11:52:25,727::resourceManager::197::ResourceManager.Request::(__init__) ResName=`Storage.5b5e5322-df22-4516-860b-361f00c46233`ReqID=`bfa5c8ea-1026-437d-9748-74090dbfa2de`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3240' at 'prepareImage'
Thread-126::DEBUG::2013-11-03 11:52:25,727::resourceManager::541::ResourceManager::(registerResource) Trying to register resource 'Storage.5b5e5322-df22-4516-860b-361f00c46233' for lock type 'shared'
Thread-126::DEBUG::2013-11-03 11:52:25,728::resourceManager::600::ResourceManager::(registerResource) Resource 'Storage.5b5e5322-df22-4516-860b-361f00c46233' is free. Now locking as 'shared' (1 active user)
Thread-126::DEBUG::2013-11-03 11:52:25,728::resourceManager::237::ResourceManager.Request::(grant) ResName=`Storage.5b5e5322-df22-4516-860b-361f00c46233`ReqID=`bfa5c8ea-1026-437d-9748-74090dbfa2de`::Granted request
Thread-126::DEBUG::2013-11-03 11:52:25,728::task::811::TaskManager.Task::(resourceAcquired) Task=`28cb4bfb-20e0-4f02-bbdf-826571b98217`::_resourcesAcquired: Storage.5b5e5322-df22-4516-860b-361f00c46233 (shared)
Thread-126::DEBUG::2013-11-03 11:52:25,728::task::974::TaskManager.Task::(_decref) Task=`28cb4bfb-20e0-4f02-bbdf-826571b98217`::ref 1 aborting False
Thread-125::DEBUG::2013-11-03 11:52:25,729::clientIF::380::vds::(createVm) Total desktops after creation of 1f0a2763-5c40-4fa3-a51c-ed98276b8e6d is 1
Thread-125::DEBUG::2013-11-03 11:52:25,729::BindingXMLRPC::986::vds::(wrapper) return vmCreate with {'status': {'message': 'Done', 'code': 0}, 'vmList': {'status': 'WaitForLaunch', 'acpiEnable': 'true', 'emulatedMachine': 'rhel6.4.0', 'vmId': '1f0a2763-5c40-4fa3-a51c-ed98276b8e6d', 'pid': '0', 'memGuaranteedSize': 1024, 'timeOffset': '0', 'keyboardLayout': 'en-us', 'displayPort': '-1', 'displaySecurePort': '-1', 'spiceSslCipherSuite': 'DEFAULT', 'cpuType': 'Penryn', 'custom': {}, 'clientIp': '', 'nicModel': 'rtl8139,pv', 'smartcardEnable': 'false', 'kvmEnable': 'true', 'transparentHugePages': 'true', 'devices': [{'device': 'qxl', 'specParams': {'vram': '65536'}, 'type': 'video', 'deviceId': '50623be3-019e-4276-a1df-2b1cdb933e69'}, {'index': '2', 'iface': 'ide', 'bootOrder': '1', 'specParams': {'path': ''}, 'readonly': 'true', 'deviceId': '49494a9a-1f6c-41aa-a9f5-189492c2bfdb', 'path': '', 'device': 'cdrom', 'shared': 'false', 'type': 'disk'}, {'index': 0, 'iface': 'virtio', 'reqsize': '0', 'format': 'cow', 'type': 'disk', 'volumeID': 'bcabc2ba-b7e1-47f9-9098-bbe19b096ad5', 'apparentsize': '262144', 'imageID': 'a544c2c3-cf3a-42c7-8e20-371344ad22da', 'specParams': {}, 'readonly': 'false', 'domainID': '5b5e5322-df22-4516-860b-361f00c46233', 'deviceId': 'a544c2c3-cf3a-42c7-8e20-371344ad22da', 'truesize': '139264', 'poolID': '9b476274-7c1c-4762-8cb4-699c2729b152', 'device': 'disk', 'shared': 'false', 'propagateErrors': 'off', 'optional': 'false'}, {'device': 'scsi', 'model': 'virtio-scsi', 'type': 'controller'}, {'nicModel': 'pv', 'macAddr': '00:1a:4a:7d:ea:72', 'linkActive': 'true', 'network': 'ovirtmgmt', 'custom': {}, 'filter': 'vdsm-no-mac-spoofing', 'specParams': {}, 'deviceId': '2bc8c2d5-2dd5-4ed6-8626-fadefdbd3fe2', 'device': 'bridge', 'type': 'interface'}, {'device': 'ich6', 'specParams': {}, 'type': 'sound', 'deviceId': '6ca24c83-e175-4a24-9803-0dba03d8cb3f'}, {'device': 'memballoon', 'specParams': {'model': 'virtio'}, 'type': 'balloon', 'deviceId': '46b9f702-4b90-4b04-85e3-6e37e9b138e9', 'target': 1048576}], 'smp': '1', 'vmType': 'kvm', 'memSize': 1024, 'displayIp': '0', 'spiceSecureChannels': 'smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard', 'smpCoresPerSocket': '1', 'vmName': 'local_vm', 'display': 'qxl', 'nice': '0'}}
Thread-126::DEBUG::2013-11-03 11:52:25,731::fileVolume::520::Storage.Volume::(validateVolumePath) validate path for bcabc2ba-b7e1-47f9-9098-bbe19b096ad5
Thread-126::INFO::2013-11-03 11:52:25,765::image::215::Storage.Image::(getChain) sdUUID=5b5e5322-df22-4516-860b-361f00c46233 imgUUID=a544c2c3-cf3a-42c7-8e20-371344ad22da chain=[<storage.fileVolume.FileVolume object at 0x2950a50>]
Thread-126::DEBUG::2013-11-03 11:52:25,770::fileVolume::520::Storage.Volume::(validateVolumePath) validate path for bcabc2ba-b7e1-47f9-9098-bbe19b096ad5
Thread-126::INFO::2013-11-03 11:52:25,775::logUtils::47::dispatcher::(wrapper) Run and protect: prepareImage, Return response: {'info': {'path': '/rhev/data-center/9b476274-7c1c-4762-8cb4-699c2729b152/5b5e5322-df22-4516-860b-361f00c46233/images/a544c2c3-cf3a-42c7-8e20-371344ad22da/bcabc2ba-b7e1-47f9-9098-bbe19b096ad5', 'volType': 'path'}, 'path': '/rhev/data-center/9b476274-7c1c-4762-8cb4-699c2729b152/5b5e5322-df22-4516-860b-361f00c46233/images/a544c2c3-cf3a-42c7-8e20-371344ad22da/bcabc2ba-b7e1-47f9-9098-bbe19b096ad5', 'chain': [{'path': '/rhev/data-center/9b476274-7c1c-4762-8cb4-699c2729b152/5b5e5322-df22-4516-860b-361f00c46233/images/a544c2c3-cf3a-42c7-8e20-371344ad22da/bcabc2ba-b7e1-47f9-9098-bbe19b096ad5', 'domainID': '5b5e5322-df22-4516-860b-361f00c46233', 'vmVolInfo': {'path': '/rhev/data-center/9b476274-7c1c-4762-8cb4-699c2729b152/5b5e5322-df22-4516-860b-361f00c46233/images/a544c2c3-cf3a-42c7-8e20-371344ad22da/bcabc2ba-b7e1-47f9-9098-bbe19b096ad5', 'volType': 'path'}, 'volumeID': 'bcabc2ba-b7e1-47f9-9098-bbe19b096ad5', 'imageID': 'a544c2c3-cf3a-42c7-8e20-371344ad22da'}]}
Thread-126::DEBUG::2013-11-03 11:52:25,775::task::1168::TaskManager.Task::(prepare) Task=`28cb4bfb-20e0-4f02-bbdf-826571b98217`::finished: {'info': {'path': '/rhev/data-center/9b476274-7c1c-4762-8cb4-699c2729b152/5b5e5322-df22-4516-860b-361f00c46233/images/a544c2c3-cf3a-42c7-8e20-371344ad22da/bcabc2ba-b7e1-47f9-9098-bbe19b096ad5', 'volType': 'path'}, 'path': '/rhev/data-center/9b476274-7c1c-4762-8cb4-699c2729b152/5b5e5322-df22-4516-860b-361f00c46233/images/a544c2c3-cf3a-42c7-8e20-371344ad22da/bcabc2ba-b7e1-47f9-9098-bbe19b096ad5', 'chain': [{'path': '/rhev/data-center/9b476274-7c1c-4762-8cb4-699c2729b152/5b5e5322-df22-4516-860b-361f00c46233/images/a544c2c3-cf3a-42c7-8e20-371344ad22da/bcabc2ba-b7e1-47f9-9098-bbe19b096ad5', 'domainID': '5b5e5322-df22-4516-860b-361f00c46233', 'vmVolInfo': {'path': '/rhev/data-center/9b476274-7c1c-4762-8cb4-699c2729b152/5b5e5322-df22-4516-860b-361f00c46233/images/a544c2c3-cf3a-42c7-8e20-371344ad22da/bcabc2ba-b7e1-47f9-9098-bbe19b096ad5', 'volType': 'path'}, 'volumeID': 'bcabc2ba-b7e1-47f9-9098-bbe19b096ad5', 'imageID': 'a544c2c3-cf3a-42c7-8e20-371344ad22da'}]}
Thread-126::DEBUG::2013-11-03 11:52:25,775::task::579::TaskManager.Task::(_updateState) Task=`28cb4bfb-20e0-4f02-bbdf-826571b98217`::moving from state preparing -> state finished
Thread-126::DEBUG::2013-11-03 11:52:25,775::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.5b5e5322-df22-4516-860b-361f00c46233': < ResourceRef 'Storage.5b5e5322-df22-4516-860b-361f00c46233', isValid: 'True' obj: 'None'>}
Thread-126::DEBUG::2013-11-03 11:52:25,775::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-126::DEBUG::2013-11-03 11:52:25,776::resourceManager::615::ResourceManager::(releaseResource) Trying to release resource 'Storage.5b5e5322-df22-4516-860b-361f00c46233'
Thread-126::DEBUG::2013-11-03 11:52:25,776::resourceManager::634::ResourceManager::(releaseResource) Released resource 'Storage.5b5e5322-df22-4516-860b-361f00c46233' (0 active users)
Thread-126::DEBUG::2013-11-03 11:52:25,776::resourceManager::640::ResourceManager::(releaseResource) Resource 'Storage.5b5e5322-df22-4516-860b-361f00c46233' is free, finding out if anyone is waiting for it.
Thread-126::DEBUG::2013-11-03 11:52:25,776::resourceManager::648::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.5b5e5322-df22-4516-860b-361f00c46233', Clearing records.
Thread-126::DEBUG::2013-11-03 11:52:25,776::task::974::TaskManager.Task::(_decref) Task=`28cb4bfb-20e0-4f02-bbdf-826571b98217`::ref 0 aborting False
Thread-126::INFO::2013-11-03 11:52:25,777::clientIF::325::vds::(prepareVolumePath) prepared volume path: /rhev/data-center/9b476274-7c1c-4762-8cb4-699c2729b152/5b5e5322-df22-4516-860b-361f00c46233/images/a544c2c3-cf3a-42c7-8e20-371344ad22da/bcabc2ba-b7e1-47f9-9098-bbe19b096ad5
Thread-126::DEBUG::2013-11-03 11:52:25,790::vm::2872::vm.Vm::(_run) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::<?xml version="1.0" encoding="utf-8"?>
<domain type="kvm">
<name>local_vm</name>
<uuid>1f0a2763-5c40-4fa3-a51c-ed98276b8e6d</uuid>
<memory>1048576</memory>
<currentMemory>1048576</currentMemory>
<vcpu>1</vcpu>
<memtune>
<min_guarantee>1048576</min_guarantee>
</memtune>
<devices>
<channel type="unix">
<target name="com.redhat.rhevm.vdsm" type="virtio"/>
<source mode="bind" path="/var/lib/libvirt/qemu/channels/1f0a2763-5c40-4fa3-a51c-ed98276b8e6d.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/1f0a2763-5c40-4fa3-a51c-ed98276b8e6d.org.qemu.guest_agent.0"/>
</channel>
<input bus="ps2" type="mouse"/>
<channel type="spicevmc">
<target name="com.redhat.spice.0" type="virtio"/>
</channel>
<graphics autoport="yes" keymap="en-us" listen="0" passwd="*****" passwdValidTo="1970-01-01T00:00:01" port="-1" tlsPort="-1" type="spice">
<channel mode="secure" name="main"/>
<channel mode="secure" name="inputs"/>
<channel mode="secure" name="cursor"/>
<channel mode="secure" name="playback"/>
<channel mode="secure" name="record"/>
<channel mode="secure" name="display"/>
<channel mode="secure" name="usbredir"/>
<channel mode="secure" name="smartcard"/>
</graphics>
<controller model="virtio-scsi" type="scsi"/>
<video>
<model heads="1" type="qxl" vram="65536"/>
</video>
<interface type="bridge">
<mac address="00:1a:4a:7d:ea:72"/>
<model type="virtio"/>
<source bridge="ovirtmgmt"/>
<filterref filter="vdsm-no-mac-spoofing"/>
<link state="up"/>
</interface>
<disk device="cdrom" snapshot="no" type="file">
<source file="" startupPolicy="optional"/>
<target bus="ide" dev="hdc"/>
<readonly/>
<serial/>
<boot order="1"/>
</disk>
<disk device="disk" snapshot="no" type="file">
<source file="/rhev/data-center/9b476274-7c1c-4762-8cb4-699c2729b152/5b5e5322-df22-4516-860b-361f00c46233/images/a544c2c3-cf3a-42c7-8e20-371344ad22da/bcabc2ba-b7e1-47f9-9098-bbe19b096ad5"/>
<target bus="virtio" dev="vda"/>
<serial>a544c2c3-cf3a-42c7-8e20-371344ad22da</serial>
<driver cache="none" error_policy="stop" io="threads" name="qemu" type="qcow2"/>
</disk>
<sound model="ich6"/>
<memballoon model="virtio"/>
</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">7BDA8401-4A6D-11CB-9351-9A12136401D2</entry>
<entry name="uuid">1f0a2763-5c40-4fa3-a51c-ed98276b8e6d</entry>
</system>
</sysinfo>
<clock adjustment="0" offset="variable">
<timer name="rtc" tickpolicy="catchup"/>
</clock>
<features>
<acpi/>
</features>
<cpu match="exact">
<model>Penryn</model>
<topology cores="1" sockets="1" threads="1"/>
</cpu>
</domain>
libvirtEventLoop::DEBUG::2013-11-03 11:52:26,383::vm::4724::vm.Vm::(_onLibvirtLifecycleEvent) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::event Started detail 0 opaque None
Thread-126::DEBUG::2013-11-03 11:52:26,465::sampling::285::vm.Vm::(start) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Start statistics collection
Thread-128::DEBUG::2013-11-03 11:52:26,479::sampling::314::vm.Vm::(run) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Stats thread started
Thread-128::DEBUG::2013-11-03 11:52:26,480::task::579::TaskManager.Task::(_updateState) Task=`06de0c6d-28e6-4c20-9139-90c3f440dc6b`::moving from state init -> state preparing
Thread-128::INFO::2013-11-03 11:52:26,480::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='5b5e5322-df22-4516-860b-361f00c46233', spUUID='9b476274-7c1c-4762-8cb4-699c2729b152', imgUUID='a544c2c3-cf3a-42c7-8e20-371344ad22da', volUUID='bcabc2ba-b7e1-47f9-9098-bbe19b096ad5', options=None)
Thread-128::DEBUG::2013-11-03 11:52:26,483::fileVolume::520::Storage.Volume::(validateVolumePath) validate path for bcabc2ba-b7e1-47f9-9098-bbe19b096ad5
Thread-128::INFO::2013-11-03 11:52:26,485::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '139264', 'apparentsize': '262144'}
Thread-128::DEBUG::2013-11-03 11:52:26,485::task::1168::TaskManager.Task::(prepare) Task=`06de0c6d-28e6-4c20-9139-90c3f440dc6b`::finished: {'truesize': '139264', 'apparentsize': '262144'}
Thread-128::DEBUG::2013-11-03 11:52:26,485::task::579::TaskManager.Task::(_updateState) Task=`06de0c6d-28e6-4c20-9139-90c3f440dc6b`::moving from state preparing -> state finished
Thread-128::DEBUG::2013-11-03 11:52:26,485::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-128::DEBUG::2013-11-03 11:52:26,485::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-128::DEBUG::2013-11-03 11:52:26,491::task::974::TaskManager.Task::(_decref) Task=`06de0c6d-28e6-4c20-9139-90c3f440dc6b`::ref 0 aborting False
Thread-126::DEBUG::2013-11-03 11:52:26,507::vmChannels::194::vds::(register) Add fileno 45 to listener's channels.
Thread-126::WARNING::2013-11-03 11:52:26,522::vm::3326::vm.Vm::(_readPauseCode) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::_readPauseCode unsupported by libvirt vm
Thread-126::DEBUG::2013-11-03 11:52:26,552::vm::2036::vm.Vm::(_startUnderlyingVm) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::_ongoingCreations released
VM Channels Listener::DEBUG::2013-11-03 11:52:26,705::vmChannels::102::vds::(_do_add_channels) fileno 45 was added to unconnected channels.
VM Channels Listener::DEBUG::2013-11-03 11:52:26,705::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 45.
VM Channels Listener::DEBUG::2013-11-03 11:52:26,705::guestIF::147::vm.Vm::(_connect) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Attempting connection to /var/lib/libvirt/qemu/channels/1f0a2763-5c40-4fa3-a51c-ed98276b8e6d.com.redhat.rhevm.vdsm
VM Channels Listener::DEBUG::2013-11-03 11:52:26,706::guestIF::150::vm.Vm::(_connect) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Connected to /var/lib/libvirt/qemu/channels/1f0a2763-5c40-4fa3-a51c-ed98276b8e6d.com.redhat.rhevm.vdsm
VM Channels Listener::DEBUG::2013-11-03 11:52:26,707::vmChannels::144::vds::(_handle_unconnected) Connecting to fileno 45 succeeded.
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:27,700::vm::579::vm.Vm::(_getCpuStats) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::CPU stats not available: 'NoneType' object is unsubscriptable
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:27,700::vm::613::vm.Vm::(_getNetworkStats) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Network stats not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:27,701::vm::633::vm.Vm::(_getDiskStats) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk hdc stats not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:27,701::vm::633::vm.Vm::(_getDiskStats) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk vda stats not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:27,701::vm::672::vm.Vm::(_getDiskLatency) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk hdc latency not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:27,701::vm::672::vm.Vm::(_getDiskLatency) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk vda latency not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:27,704::vm::579::vm.Vm::(_getCpuStats) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::CPU stats not available: 'NoneType' object is unsubscriptable
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:27,704::vm::613::vm.Vm::(_getNetworkStats) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Network stats not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:27,704::vm::633::vm.Vm::(_getDiskStats) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk hdc stats not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:27,705::vm::633::vm.Vm::(_getDiskStats) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk vda stats not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:27,705::vm::672::vm.Vm::(_getDiskLatency) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk hdc latency not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:27,705::vm::672::vm.Vm::(_getDiskLatency) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk vda latency not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:32,712::vm::579::vm.Vm::(_getCpuStats) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::CPU stats not available: 'NoneType' object is unsubscriptable
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:32,712::vm::633::vm.Vm::(_getDiskStats) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk hdc stats not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:32,713::vm::633::vm.Vm::(_getDiskStats) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk vda stats not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:32,713::vm::672::vm.Vm::(_getDiskLatency) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk hdc latency not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:32,713::vm::672::vm.Vm::(_getDiskLatency) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk vda latency not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:32,715::vm::579::vm.Vm::(_getCpuStats) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::CPU stats not available: 'NoneType' object is unsubscriptable
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:32,716::vm::633::vm.Vm::(_getDiskStats) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk hdc stats not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:32,716::vm::633::vm.Vm::(_getDiskStats) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk vda stats not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:32,716::vm::672::vm.Vm::(_getDiskLatency) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk hdc latency not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:32,716::vm::672::vm.Vm::(_getDiskLatency) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk vda latency not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:37,722::vm::579::vm.Vm::(_getCpuStats) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::CPU stats not available: 'NoneType' object is unsubscriptable
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:37,723::vm::633::vm.Vm::(_getDiskStats) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk hdc stats not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:37,723::vm::633::vm.Vm::(_getDiskStats) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk vda stats not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:37,723::vm::672::vm.Vm::(_getDiskLatency) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk hdc latency not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:37,723::vm::672::vm.Vm::(_getDiskLatency) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk vda latency not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:37,725::vm::579::vm.Vm::(_getCpuStats) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::CPU stats not available: 'NoneType' object is unsubscriptable
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:37,726::vm::633::vm.Vm::(_getDiskStats) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk hdc stats not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:37,726::vm::633::vm.Vm::(_getDiskStats) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk vda stats not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:37,726::vm::672::vm.Vm::(_getDiskLatency) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk hdc latency not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:37,726::vm::672::vm.Vm::(_getDiskLatency) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk vda latency not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:42,733::vm::633::vm.Vm::(_getDiskStats) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk hdc stats not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:42,733::vm::633::vm.Vm::(_getDiskStats) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk vda stats not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:42,734::vm::672::vm.Vm::(_getDiskLatency) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk hdc latency not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:42,734::vm::672::vm.Vm::(_getDiskLatency) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk vda latency not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:42,736::vm::633::vm.Vm::(_getDiskStats) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk hdc stats not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:42,736::vm::633::vm.Vm::(_getDiskStats) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk vda stats not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:42,736::vm::672::vm.Vm::(_getDiskLatency) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk hdc latency not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:42,737::vm::672::vm.Vm::(_getDiskLatency) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk vda latency not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:47,742::vm::633::vm.Vm::(_getDiskStats) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk hdc stats not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:47,743::vm::633::vm.Vm::(_getDiskStats) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk vda stats not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:47,743::vm::672::vm.Vm::(_getDiskLatency) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk hdc latency not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:47,743::vm::672::vm.Vm::(_getDiskLatency) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk vda latency not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:47,745::vm::633::vm.Vm::(_getDiskStats) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk hdc stats not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:47,746::vm::633::vm.Vm::(_getDiskStats) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk vda stats not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:47,746::vm::672::vm.Vm::(_getDiskLatency) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk hdc latency not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:47,746::vm::672::vm.Vm::(_getDiskLatency) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk vda latency not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:52,754::vm::633::vm.Vm::(_getDiskStats) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk hdc stats not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:52,754::vm::633::vm.Vm::(_getDiskStats) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk vda stats not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:52,754::vm::672::vm.Vm::(_getDiskLatency) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk hdc latency not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:52,754::vm::672::vm.Vm::(_getDiskLatency) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk vda latency not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:52,756::vm::633::vm.Vm::(_getDiskStats) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk hdc stats not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:52,756::vm::633::vm.Vm::(_getDiskStats) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk vda stats not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:52,757::vm::672::vm.Vm::(_getDiskLatency) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk hdc latency not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:52,757::vm::672::vm.Vm::(_getDiskLatency) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk vda latency not available
VM Channels Listener::DEBUG::2013-11-03 11:52:56,737::vmChannels::91::vds::(_handle_timeouts) Timeout on fileno 45.
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:57,764::vm::633::vm.Vm::(_getDiskStats) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk hdc stats not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:57,765::vm::633::vm.Vm::(_getDiskStats) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk vda stats not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:57,765::vm::672::vm.Vm::(_getDiskLatency) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk hdc latency not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:57,765::vm::672::vm.Vm::(_getDiskLatency) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk vda latency not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:57,768::vm::633::vm.Vm::(_getDiskStats) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk hdc stats not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:57,768::vm::633::vm.Vm::(_getDiskStats) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk vda stats not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:57,768::vm::672::vm.Vm::(_getDiskLatency) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk hdc latency not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:52:57,769::vm::672::vm.Vm::(_getDiskLatency) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk vda latency not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:53:02,782::vm::633::vm.Vm::(_getDiskStats) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk hdc stats not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:53:02,783::vm::633::vm.Vm::(_getDiskStats) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk vda stats not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:53:02,783::vm::672::vm.Vm::(_getDiskLatency) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk hdc latency not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:53:02,784::vm::672::vm.Vm::(_getDiskLatency) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk vda latency not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:53:02,786::vm::633::vm.Vm::(_getDiskStats) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk hdc stats not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:53:02,787::vm::633::vm.Vm::(_getDiskStats) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk vda stats not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:53:02,787::vm::672::vm.Vm::(_getDiskLatency) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk hdc latency not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:53:02,787::vm::672::vm.Vm::(_getDiskLatency) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk vda latency not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:53:07,795::vm::633::vm.Vm::(_getDiskStats) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk hdc stats not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:53:07,795::vm::633::vm.Vm::(_getDiskStats) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk vda stats not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:53:07,795::vm::672::vm.Vm::(_getDiskLatency) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk hdc latency not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:53:07,795::vm::672::vm.Vm::(_getDiskLatency) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk vda latency not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:53:07,797::vm::633::vm.Vm::(_getDiskStats) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk hdc stats not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:53:07,797::vm::633::vm.Vm::(_getDiskStats) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk vda stats not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:53:07,797::vm::672::vm.Vm::(_getDiskLatency) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk hdc latency not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:53:07,797::vm::672::vm.Vm::(_getDiskLatency) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk vda latency not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:53:12,800::vm::633::vm.Vm::(_getDiskStats) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk hdc stats not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:53:12,800::vm::633::vm.Vm::(_getDiskStats) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk vda stats not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:53:12,800::vm::672::vm.Vm::(_getDiskLatency) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk hdc latency not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:53:12,800::vm::672::vm.Vm::(_getDiskLatency) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk vda latency not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:53:12,802::vm::633::vm.Vm::(_getDiskStats) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk hdc stats not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:53:12,802::vm::633::vm.Vm::(_getDiskStats) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk vda stats not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:53:12,803::vm::672::vm.Vm::(_getDiskLatency) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk hdc latency not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:53:12,803::vm::672::vm.Vm::(_getDiskLatency) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk vda latency not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:53:17,810::vm::633::vm.Vm::(_getDiskStats) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk hdc stats not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:53:17,810::vm::633::vm.Vm::(_getDiskStats) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk vda stats not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:53:17,810::vm::672::vm.Vm::(_getDiskLatency) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk hdc latency not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:53:17,810::vm::672::vm.Vm::(_getDiskLatency) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk vda latency not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:53:17,812::vm::633::vm.Vm::(_getDiskStats) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk hdc stats not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:53:17,812::vm::633::vm.Vm::(_getDiskStats) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk vda stats not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:53:17,812::vm::672::vm.Vm::(_getDiskLatency) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk hdc latency not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:53:17,812::vm::672::vm.Vm::(_getDiskLatency) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk vda latency not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:53:22,819::vm::633::vm.Vm::(_getDiskStats) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk hdc stats not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:53:22,820::vm::633::vm.Vm::(_getDiskStats) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk vda stats not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:53:22,820::vm::672::vm.Vm::(_getDiskLatency) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk hdc latency not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:53:22,820::vm::672::vm.Vm::(_getDiskLatency) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk vda latency not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:53:22,822::vm::633::vm.Vm::(_getDiskStats) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk hdc stats not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:53:22,822::vm::633::vm.Vm::(_getDiskStats) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk vda stats not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:53:22,822::vm::672::vm.Vm::(_getDiskLatency) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk hdc latency not available
GuestMonitor-local_vm::DEBUG::2013-11-03 11:53:22,822::vm::672::vm.Vm::(_getDiskLatency) vmId=`1f0a2763-5c40-4fa3-a51c-ed98276b8e6d`::Disk vda latency not available
Thread-128::DEBUG::2013-11-03 11:53:26,670::task::579::TaskManager.Task::(_updateState) Task=`ed5d6a18-6ae7-4732-b36e-977642b83e81`::moving from state init -> state preparing
Thread-128::INFO::2013-11-03 11:53:26,671::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='5b5e5322-df22-4516-860b-361f00c46233', spUUID='9b476274-7c1c-4762-8cb4-699c2729b152', imgUUID='a544c2c3-cf3a-42c7-8e20-371344ad22da', volUUID='bcabc2ba-b7e1-47f9-9098-bbe19b096ad5', options=None)
Thread-128::DEBUG::2013-11-03 11:53:26,673::fileVolume::520::Storage.Volume::(validateVolumePath) validate path for bcabc2ba-b7e1-47f9-9098-bbe19b096ad5
Thread-128::INFO::2013-11-03 11:53:26,674::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '139264', 'apparentsize': '262144'}
Thread-128::DEBUG::2013-11-03 11:53:26,674::task::1168::TaskManager.Task::(prepare) Task=`ed5d6a18-6ae7-4732-b36e-977642b83e81`::finished: {'truesize': '139264', 'apparentsize': '262144'}
Thread-128::DEBUG::2013-11-03 11:53:26,675::task::579::TaskManager.Task::(_updateState) Task=`ed5d6a18-6ae7-4732-b36e-977642b83e81`::moving from state preparing -> state finished
Thread-128::DEBUG::2013-11-03 11:53:26,675::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-128::DEBUG::2013-11-03 11:53:26,675::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-128::DEBUG::2013-11-03 11:53:26,675::task::974::TaskManager.Task::(_decref) Task=`ed5d6a18-6ae7-4732-b36e-977642b83e81`::ref 0 aborting False
VM Channels Listener::DEBUG::2013-11-03 11:53:26,771::vmChannels::91::vds::(_handle_timeouts) Timeout on fileno 45.
2013-11-03 11:56:03,568 INFO [org.ovirt.engine.core.bll.RunVmCommand] (ajp--127.0.0.1-8702-3) [367f34e] Lock Acquired to object EngineLock [exclusiveLocks= key: 1f0a2763-5c40-4fa3-a51c-ed98276b8e6d value: VM
, sharedLocks= ]
2013-11-03 11:56:03,617 INFO [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (ajp--127.0.0.1-8702-3) [367f34e] START, IsVmDuringInitiatingVDSCommand( vmId = 1f0a2763-5c40-4fa3-a51c-ed98276b8e6d), log id: b0ac657
2013-11-03 11:56:03,618 INFO [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (ajp--127.0.0.1-8702-3) [367f34e] FINISH, IsVmDuringInitiatingVDSCommand, return: false, log id: b0ac657
2013-11-03 11:56:03,662 INFO [org.ovirt.engine.core.bll.RunVmCommand] (pool-6-thread-48) [367f34e] Running command: RunVmCommand internal: false. Entities affected : ID: 1f0a2763-5c40-4fa3-a51c-ed98276b8e6d Type: VM
2013-11-03 11:56:03,721 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IsoPrefixVDSCommand] (pool-6-thread-48) [367f34e] START, IsoPrefixVDSCommand( storagePoolId = 9b476274-7c1c-4762-8cb4-699c2729b152, ignoreFailoverLimit = false), log id: 32756d37
2013-11-03 11:56:03,722 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IsoPrefixVDSCommand] (pool-6-thread-48) [367f34e] FINISH, IsoPrefixVDSCommand, return: /rhev/data-center/mnt/livecd.localdomain:_var_lib_exports_iso/9ba047f0-1883-4f45-b022-bbf6afbd5784/images/11111111-1111-1111-1111-111111111111, log id: 32756d37
2013-11-03 11:56:03,730 INFO [org.ovirt.engine.core.vdsbroker.CreateVmVDSCommand] (pool-6-thread-48) [367f34e] START, CreateVmVDSCommand(HostName = local_host, HostId = ea3dc2a8-70c1-4921-9ad5-27d1e9c21705, vmId=1f0a2763-5c40-4fa3-a51c-ed98276b8e6d, vm=VM [local_vm]), log id: 241b5a6c
2013-11-03 11:56:03,737 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] (pool-6-thread-48) [367f34e] START, CreateVDSCommand(HostName = local_host, HostId = ea3dc2a8-70c1-4921-9ad5-27d1e9c21705, vmId=1f0a2763-5c40-4fa3-a51c-ed98276b8e6d, vm=VM [local_vm]), log id: c9394cf
2013-11-03 11:56:03,781 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] (pool-6-thread-48) [367f34e] org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand spiceSslCipherSuite=DEFAULT,memSize=1024,kvmEnable=true,smp=1,vmType=kvm,emulatedMachine=rhel6.4.0,keyboardLayout=en-us,memGuaranteedSize=1024,nice=0,display=qxl,smartcardEnable=false,smpCoresPerSocket=1,spiceSecureChannels=smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard,timeOffset=0,transparentHugePages=true,vmId=1f0a2763-5c40-4fa3-a51c-ed98276b8e6d,devices=[Ljava.util.HashMap;@67c2cab9,acpiEnable=true,vmName=local_vm,cpuType=Penryn,custom={}
2013-11-03 11:56:03,783 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] (pool-6-thread-48) [367f34e] FINISH, CreateVDSCommand, log id: c9394cf
2013-11-03 11:56:03,788 INFO [org.ovirt.engine.core.vdsbroker.CreateVmVDSCommand] (pool-6-thread-48) [367f34e] FINISH, CreateVmVDSCommand, return: WaitForLaunch, log id: 241b5a6c
2013-11-03 11:56:03,789 INFO [org.ovirt.engine.core.bll.RunVmCommand] (pool-6-thread-48) [367f34e] Lock freed to object EngineLock [exclusiveLocks= key: 1f0a2763-5c40-4fa3-a51c-ed98276b8e6d value: VM
, sharedLocks= ]
2013-11-03 11:56:03,813 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (pool-6-thread-48) [367f34e] Correlation ID: 367f34e, Job ID: 2faf048e-e176-41e2-8618-b6ecc14e08b8, Call Stack: null, Custom Event ID: -1, Message: VM local_vm was started by admin@internal (Host: local_host).
_______________________________________________
Engine-devel mailing list
Engine-devel@ovirt.org
http://lists.ovirt.org/mailman/listinfo/engine-devel
