[Users] ovirt not seeing a VM has started.

Hi I have my oVirt setup to the point where I can add VM. I am using Gluster and to get it to be able to add VMs I had to run "setsebool -P virt_use_fusefs=on" once I did this it seems to work fine for added VMs. I have added a Fedora 17 vm, when I start the VM in oVirt, the management interface never see it as started, just always has the hour glass next to it. If I do a PS on the node I can see the VM is indeed started and can see the qemu-kvm process for that VM. There are no deny messages in audit.log on the node. The message log on the node has this message: "VM start: vdsm vm.Vm WARNING vmId=`4abdba0d-aa1f-48f1-8160-3cde63165057`::_readPauseCode unsupported by libvirt vm". Not sure if this is related. The vdsm log when I click on the run VM: Thread-1539::DEBUG::2012-10-30 09:56:09,203::BindingXMLRPC::859::vds::(wrapper) client [192.168.1.10]::call vmCreate with ({'custom': {'viodiskcache': 'writeback'}, 'keyboardLayout': 'en-us', 'kvmEnable': 'true', 'pitReinjection': 'false', 'acpiEnable': 'true', 'emulatedMachine': 'pc-0.14', 'vmId': '4abdba0d-aa1f-48f1-8160-3cde63165057', 'devices': [{'device': 'qxl', 'specParams': {'vram': '65536'}, 'type': 'video', 'deviceId': '25ada4cb-1108-491b-8d2c-c05cb353cc99'}, {'index': '2', 'iface': 'ide', 'bootOrder': '1', 'specParams': {'path': 'Fedora-17-x86_64-DVD.iso'}, 'readonly': 'true', 'deviceId': '1b62fc2d-88e5-42e0-9666-3de861a71c44', 'device': 'cdrom', 'path': '/rhev/data-center/640fa36c-1da8-11e2-86f7-1078d2e9dece/65f95655-5bbe-47e4-8d3a-6e2ffc5c7761/images/11111111-1111-1111-1111-111111111111/Fedora-17-x86_64-DVD.iso', 'type': 'disk'}, {'index': 0, 'iface': 'virtio', 'format': 'raw', 'type': 'disk', 'volumeID': '12413fe4-a694-439b-95d8-40d5a576dada', 'imageID': '025d5960-23db-4e07-98c8-4c9682155eb1', 'specParams': {}, 'readonly': 'false', 'domainID': 'e552b5fd-30fb-4e18-8bc4-26517f11a283', 'deviceId': '025d5960-23db-4e07-98c8-4c9682155eb1', 'poolID': '640fa36c-1da8-11e2-86f7-1078d2e9dece', 'device': 'disk', 'shared': 'false', 'propagateErrors': 'off', 'optional': 'false'}, {'nicModel': 'pv', 'macAddr': '00:1a:4a:70:83:00', 'network': 'ovirtmgmt', 'specParams': {}, 'deviceId': '80841d17-f758-46c8-84bc-0346072c4156', 'device': 'bridge', 'type': 'interface'}, {'device': 'memballoon', 'specParams': {'model': 'virtio'}, 'type': 'balloon', 'deviceId': '09f59ef5-b17f-49ea-99e6-8ee7bcca64a1'}], 'smp': '2', 'vmType': 'kvm', 'timeOffset': '0', 'memSize': 1024, 'spiceSslCipherSuite': 'DEFAULT', 'cpuType': 'Conroe', 'spiceSecureChannels': 'smain,sinputs,scursor,splayback,srecord,sdisplay', 'smpCoresPerSocket': '2', 'vmName': 'bsdlinux04vm', 'display': 'qxl', 'transparentHugePages': 'true', 'nice': '0'},) {} flowID [8a5456c] Thread-1539::INFO::2012-10-30 09:56:09,203::API::601::vds::(_getNetworkIp) network None: using 0 Thread-1539::INFO::2012-10-30 09:56:09,204::API::228::vds::(create) vmContainerLock acquired by vm 4abdba0d-aa1f-48f1-8160-3cde63165057 Thread-1540::DEBUG::2012-10-30 09:56:09,207::vm::564::vm.Vm::(_startUnderlyingVm) vmId=`4abdba0d-aa1f-48f1-8160-3cde63165057`::Start Thread-1539::DEBUG::2012-10-30 09:56:09,207::API::244::vds::(create) Total desktops after creation of 4abdba0d-aa1f-48f1-8160-3cde63165057 is 1 Thread-1539::DEBUG::2012-10-30 09:56:09,208::BindingXMLRPC::865::vds::(wrapper) return vmCreate with {'status': {'message': 'Done', 'code': 0}, 'vmList': {'status': 'WaitForLaunch', 'acpiEnable': 'true', 'emulatedMachine': 'pc-0.14', 'vmId': '4abdba0d-aa1f-48f1-8160-3cde63165057', 'pid': '0', 'timeOffset': '0', 'displayPort': '-1', 'displaySecurePort': '-1', 'spiceSslCipherSuite': 'DEFAULT', 'cpuType': 'Conroe', 'custom': {'viodiskcache': 'writeback'}, 'clientIp': '', 'nicModel': 'rtl8139,pv', 'keyboardLayout': 'en-us', 'kvmEnable': 'true', 'pitReinjection': 'false', 'transparentHugePages': 'true', 'devices': [{'device': 'qxl', 'specParams': {'vram': '65536'}, 'type': 'video', 'deviceId': '25ada4cb-1108-491b-8d2c-c05cb353cc99'}, {'index': '2', 'iface': 'ide', 'bootOrder': '1', 'specParams': {'path': 'Fedora-17-x86_64-DVD.iso'}, 'readonly': 'true', 'deviceId': '1b62fc2d-88e5-42e0-9666-3de861a71c44', 'device': 'cdrom', 'path': '/rhev/data-center/640fa36c-1da8-11e2-86f7-1078d2e9dece/65f95655-5bbe-47e4-8d3a-6e2ffc5c7761/images/11111111-1111-1111-1111-111111111111/Fedora-17-x86_64-DVD.iso', 'type': 'disk'}, {'index': 0, 'iface': 'virtio', 'format': 'raw', 'type': 'disk', 'volumeID': '12413fe4-a694-439b-95d8-40d5a576dada', 'imageID': '025d5960-23db-4e07-98c8-4c9682155eb1', 'specParams': {}, 'readonly': 'false', 'domainID': 'e552b5fd-30fb-4e18-8bc4-26517f11a283', 'deviceId': '025d5960-23db-4e07-98c8-4c9682155eb1', 'poolID': '640fa36c-1da8-11e2-86f7-1078d2e9dece', 'device': 'disk', 'shared': 'false', 'propagateErrors': 'off', 'optional': 'false'}, {'nicModel': 'pv', 'macAddr': '00:1a:4a:70:83:00', 'network': 'ovirtmgmt', 'specParams': {}, 'deviceId': '80841d17-f758-46c8-84bc-0346072c4156', 'device': 'bridge', 'type': 'interface'}, {'device': 'memballoon', 'specParams': {'model': 'virtio'}, 'type': 'balloon', 'deviceId': '09f59ef5-b17f-49ea-99e6-8ee7bcca64a1'}], 'smp': '2', 'vmType': 'kvm', 'memSize': 1024, 'displayIp': '0', 'spiceSecureChannels': 'smain,sinputs,scursor,splayback,srecord,sdisplay', 'smpCoresPerSocket': '2', 'vmName': 'bsdlinux04vm', 'display': 'qxl', 'nice': '0'}} Thread-1540::DEBUG::2012-10-30 09:56:09,208::vm::568::vm.Vm::(_startUnderlyingVm) vmId=`4abdba0d-aa1f-48f1-8160-3cde63165057`::_ongoingCreations acquired Thread-1540::INFO::2012-10-30 09:56:09,210::libvirtvm::1285::vm.Vm::(_run) vmId=`4abdba0d-aa1f-48f1-8160-3cde63165057`::VM wrapper has started Thread-1540::DEBUG::2012-10-30 09:56:09,211::task::588::TaskManager.Task::(_updateState) Task=`f91ddc64-360b-4f33-bb53-9c6436a6a6d4`::moving from state init -> state preparing Thread-1540::INFO::2012-10-30 09:56:09,211::logUtils::37::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='e552b5fd-30fb-4e18-8bc4-26517f11a283', spUUID='640fa36c-1da8-11e2-86f7-1078d2e9dece', imgUUID='025d5960-23db-4e07-98c8-4c9682155eb1', volUUID='12413fe4-a694-439b-95d8-40d5a576dada', options=None) Thread-1540::DEBUG::2012-10-30 09:56:09,212::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283`ReqID=`a4d63aa4-f9af-48c3-b57f-68149d3ea523`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource' Thread-1540::DEBUG::2012-10-30 09:56:09,212::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283' for lock type 'shared' Thread-1540::DEBUG::2012-10-30 09:56:09,212::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283' is free. Now locking as 'shared' (1 active user) Thread-1540::DEBUG::2012-10-30 09:56:09,213::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283`ReqID=`a4d63aa4-f9af-48c3-b57f-68149d3ea523`::Granted request Thread-1540::DEBUG::2012-10-30 09:56:09,213::task::817::TaskManager.Task::(resourceAcquired) Task=`f91ddc64-360b-4f33-bb53-9c6436a6a6d4`::_resourcesAcquired: Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283 (shared) Thread-1540::DEBUG::2012-10-30 09:56:09,213::task::978::TaskManager.Task::(_decref) Task=`f91ddc64-360b-4f33-bb53-9c6436a6a6d4`::ref 1 aborting False Thread-1540::DEBUG::2012-10-30 09:56:09,216::fileVolume::535::Storage.Volume::(validateVolumePath) validate path for 12413fe4-a694-439b-95d8-40d5a576dada Thread-1540::DEBUG::2012-10-30 09:56:09,220::fileVolume::535::Storage.Volume::(validateVolumePath) validate path for 12413fe4-a694-439b-95d8-40d5a576dada Thread-1540::INFO::2012-10-30 09:56:09,221::logUtils::39::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '0', 'apparentsize': '8589934592'} Thread-1540::DEBUG::2012-10-30 09:56:09,221::task::1172::TaskManager.Task::(prepare) Task=`f91ddc64-360b-4f33-bb53-9c6436a6a6d4`::finished: {'truesize': '0', 'apparentsize': '8589934592'} Thread-1540::DEBUG::2012-10-30 09:56:09,222::task::588::TaskManager.Task::(_updateState) Task=`f91ddc64-360b-4f33-bb53-9c6436a6a6d4`::moving from state preparing -> state finished Thread-1540::DEBUG::2012-10-30 09:56:09,222::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283': < ResourceRef 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283', isValid: 'True' obj: 'None'>} Thread-1540::DEBUG::2012-10-30 09:56:09,222::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-1540::DEBUG::2012-10-30 09:56:09,222::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283' Thread-1540::DEBUG::2012-10-30 09:56:09,223::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283' (0 active users) Thread-1540::DEBUG::2012-10-30 09:56:09,223::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283' is free, finding out if anyone is waiting for it. Thread-1540::DEBUG::2012-10-30 09:56:09,223::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283', Clearing records. Thread-1540::DEBUG::2012-10-30 09:56:09,223::task::978::TaskManager.Task::(_decref) Task=`f91ddc64-360b-4f33-bb53-9c6436a6a6d4`::ref 0 aborting False Thread-1540::INFO::2012-10-30 09:56:09,224::clientIF::274::vds::(prepareVolumePath) prepared volume path: /rhev/data-center/640fa36c-1da8-11e2-86f7-1078d2e9dece/65f95655-5bbe-47e4-8d3a-6e2ffc5c7761/images/11111111-1111-1111-1111-111111111111/Fedora-17-x86_64-DVD.iso Thread-1540::DEBUG::2012-10-30 09:56:09,224::task::588::TaskManager.Task::(_updateState) Task=`c1701ef5-96d8-4036-a5cb-7a285152d84f`::moving from state init -> state preparing Thread-1540::INFO::2012-10-30 09:56:09,224::logUtils::37::dispatcher::(wrapper) Run and protect: prepareImage(sdUUID='e552b5fd-30fb-4e18-8bc4-26517f11a283', spUUID='640fa36c-1da8-11e2-86f7-1078d2e9dece', imgUUID='025d5960-23db-4e07-98c8-4c9682155eb1', volUUID='12413fe4-a694-439b-95d8-40d5a576dada') Thread-1540::DEBUG::2012-10-30 09:56:09,225::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283`ReqID=`1fd9533e-6b8a-458d-a4d2-001f0cc93ac2`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource' Thread-1540::DEBUG::2012-10-30 09:56:09,225::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283' for lock type 'shared' Thread-1540::DEBUG::2012-10-30 09:56:09,225::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283' is free. Now locking as 'shared' (1 active user) Thread-1540::DEBUG::2012-10-30 09:56:09,225::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283`ReqID=`1fd9533e-6b8a-458d-a4d2-001f0cc93ac2`::Granted request Thread-1540::DEBUG::2012-10-30 09:56:09,226::task::817::TaskManager.Task::(resourceAcquired) Task=`c1701ef5-96d8-4036-a5cb-7a285152d84f`::_resourcesAcquired: Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283 (shared) Thread-1540::DEBUG::2012-10-30 09:56:09,226::task::978::TaskManager.Task::(_decref) Task=`c1701ef5-96d8-4036-a5cb-7a285152d84f`::ref 1 aborting False Thread-1540::DEBUG::2012-10-30 09:56:09,227::fileVolume::535::Storage.Volume::(validateVolumePath) validate path for 12413fe4-a694-439b-95d8-40d5a576dada Thread-1540::INFO::2012-10-30 09:56:09,234::image::357::Storage.Image::(getChain) sdUUID=e552b5fd-30fb-4e18-8bc4-26517f11a283 imgUUID=025d5960-23db-4e07-98c8-4c9682155eb1 chain=[<storage.fileVolume.FileVolume instance at 0x7f82442cb0e0>] Thread-1540::INFO::2012-10-30 09:56:09,237::logUtils::39::dispatcher::(wrapper) Run and protect: prepareImage, Return response: {'path': '/rhev/data-center/640fa36c-1da8-11e2-86f7-1078d2e9dece/e552b5fd-30fb-4e18-8bc4-26517f11a283/images/025d5960-23db-4e07-98c8-4c9682155eb1/12413fe4-a694-439b-95d8-40d5a576dada', 'chain': [{'path': '/rhev/data-center/640fa36c-1da8-11e2-86f7-1078d2e9dece/e552b5fd-30fb-4e18-8bc4-26517f11a283/images/025d5960-23db-4e07-98c8-4c9682155eb1/12413fe4-a694-439b-95d8-40d5a576dada', 'domainID': 'e552b5fd-30fb-4e18-8bc4-26517f11a283', 'volumeID': '12413fe4-a694-439b-95d8-40d5a576dada', 'imageID': '025d5960-23db-4e07-98c8-4c9682155eb1'}]} Thread-1540::DEBUG::2012-10-30 09:56:09,237::task::1172::TaskManager.Task::(prepare) Task=`c1701ef5-96d8-4036-a5cb-7a285152d84f`::finished: {'path': '/rhev/data-center/640fa36c-1da8-11e2-86f7-1078d2e9dece/e552b5fd-30fb-4e18-8bc4-26517f11a283/images/025d5960-23db-4e07-98c8-4c9682155eb1/12413fe4-a694-439b-95d8-40d5a576dada', 'chain': [{'path': '/rhev/data-center/640fa36c-1da8-11e2-86f7-1078d2e9dece/e552b5fd-30fb-4e18-8bc4-26517f11a283/images/025d5960-23db-4e07-98c8-4c9682155eb1/12413fe4-a694-439b-95d8-40d5a576dada', 'domainID': 'e552b5fd-30fb-4e18-8bc4-26517f11a283', 'volumeID': '12413fe4-a694-439b-95d8-40d5a576dada', 'imageID': '025d5960-23db-4e07-98c8-4c9682155eb1'}]} Thread-1540::DEBUG::2012-10-30 09:56:09,237::task::588::TaskManager.Task::(_updateState) Task=`c1701ef5-96d8-4036-a5cb-7a285152d84f`::moving from state preparing -> state finished Thread-1540::DEBUG::2012-10-30 09:56:09,237::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283': < ResourceRef 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283', isValid: 'True' obj: 'None'>} Thread-1540::DEBUG::2012-10-30 09:56:09,237::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-1540::DEBUG::2012-10-30 09:56:09,238::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283' Thread-1540::DEBUG::2012-10-30 09:56:09,238::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283' (0 active users) Thread-1540::DEBUG::2012-10-30 09:56:09,238::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283' is free, finding out if anyone is waiting for it. Thread-1540::DEBUG::2012-10-30 09:56:09,238::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283', Clearing records. Thread-1540::DEBUG::2012-10-30 09:56:09,239::task::978::TaskManager.Task::(_decref) Task=`c1701ef5-96d8-4036-a5cb-7a285152d84f`::ref 0 aborting False Thread-1540::INFO::2012-10-30 09:56:09,239::clientIF::274::vds::(prepareVolumePath) prepared volume path: /rhev/data-center/640fa36c-1da8-11e2-86f7-1078d2e9dece/e552b5fd-30fb-4e18-8bc4-26517f11a283/images/025d5960-23db-4e07-98c8-4c9682155eb1/12413fe4-a694-439b-95d8-40d5a576dada Thread-1540::DEBUG::2012-10-30 09:56:09,249::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/libexec/vdsm/hooks/before_vm_start/50_hugepages' (cwd None) Thread-1540::DEBUG::2012-10-30 09:56:09,375::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0 Thread-1540::INFO::2012-10-30 09:56:09,376::hooks::72::root::(_runHooksDir) Thread-1540::DEBUG::2012-10-30 09:56:09,376::libvirtvm::1338::vm.Vm::(_run) vmId=`4abdba0d-aa1f-48f1-8160-3cde63165057`::<?xml version="1.0" encoding="utf-8"?> <domain type="kvm"> <name>bsdlinux04vm</name> <uuid>4abdba0d-aa1f-48f1-8160-3cde63165057</uuid> <memory>1048576</memory> <currentMemory>1048576</currentMemory> <vcpu>2</vcpu> <devices> <channel type="unix"> <target name="com.redhat.rhevm.vdsm" type="virtio"/> <source mode="bind" path="/var/lib/libvirt/qemu/channels/bsdlinux04vm.com.redhat.rhevm.vdsm"/> </channel> <input bus="ps2" type="mouse"/> <channel type="spicevmc"> <target name="com.redhat.spice.0" type="virtio"/> </channel> <graphics autoport="yes" keymap="en-us" 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"/> </graphics> <console type="pty"> <target port="0" type="virtio"/> </console> <video> <model heads="1" type="qxl" vram="65536"/> </video> <interface type="bridge"> <mac address="00:1a:4a:70:83:00"/> <model type="virtio"/> <source bridge="ovirtmgmt"/> </interface> <memballoon model="virtio"/> <disk device="cdrom" snapshot="no" type="file"> <source file="/rhev/data-center/640fa36c-1da8-11e2-86f7-1078d2e9dece/65f95655-5bbe-47e4-8d3a-6e2ffc5c7761/images/11111111-1111-1111-1111-111111111111/Fedora-17-x86_64-DVD.iso" startupPolicy="optional"/> <target bus="ide" dev="hdc"/> <readonly/> <serial></serial> <boot order="1"/> </disk> <disk device="disk" snapshot="no" type="file"> <source file="/rhev/data-center/640fa36c-1da8-11e2-86f7-1078d2e9dece/e552b5fd-30fb-4e18-8bc4-26517f11a283/images/025d5960-23db-4e07-98c8-4c9682155eb1/12413fe4-a694-439b-95d8-40d5a576dada"/> <target bus="virtio" dev="vda"/> <serial>025d5960-23db-4e07-98c8-4c9682155eb1</serial> <driver cache="writeback" error_policy="stop" io="threads" name="qemu" type="raw"/> </disk> </devices> <os> <type arch="x86_64" machine="pc-0.14">hvm</type> <smbios mode="sysinfo"/> </os> <sysinfo type="smbios"> <system> <entry name="manufacturer">Red Hat</entry> <entry name="product">RHEV Hypervisor</entry> <entry name="version">17-1</entry> <entry name="serial">4C4C4544-0059-4810-8034-B7C04F463253_d4:ae:52:a3:1c:1e</entry> <entry name="uuid">4abdba0d-aa1f-48f1-8160-3cde63165057</entry> </system> </sysinfo> <clock adjustment="0" offset="variable"> <timer name="rtc" tickpolicy="catchup"/> </clock> <features> <acpi/> </features> <cpu match="exact"> <model>Conroe</model> <topology cores="2" sockets="1" threads="1"/> </cpu> </domain> libvirtEventLoop::DEBUG::2012-10-30 09:56:10,075::libvirtvm::2409::vm.Vm::(_onLibvirtLifecycleEvent) vmId=`4abdba0d-aa1f-48f1-8160-3cde63165057`::event Started detail 0 opaque None Thread-1540::DEBUG::2012-10-30 09:56:10,188::utils::329::vm.Vm::(start) vmId=`4abdba0d-aa1f-48f1-8160-3cde63165057`::Start statistics collection Thread-1542::DEBUG::2012-10-30 09:56:10,188::utils::358::vm.Vm::(run) vmId=`4abdba0d-aa1f-48f1-8160-3cde63165057`::Stats thread started Thread-1542::DEBUG::2012-10-30 09:56:10,189::task::588::TaskManager.Task::( _updateState) Task=`6a004d5d-63a9-4ffb-a887-8f7d5c6179c7`::moving from state init -> state preparing Thread-1542::INFO::2012-10-30 09:56:10,190::logUtils::37::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='e552b5fd-30fb-4e18-8bc4-26517f11a283', spUUID='640fa36c-1da8-11e2-86f7-1078d2e9dece', imgUUID='025d5960-23db-4e07-98c8-4c9682155eb1', volUUID='12413fe4-a694-439b-95d8-40d5a576dada', options=None) Thread-1542::DEBUG::2012-10-30 09:56:10,191::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283`ReqID=`057d2200-a704-4de4-a45b-2771d72f30bb`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource' Thread-1542::DEBUG::2012-10-30 09:56:10,191::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283' for lock type 'shared' Thread-1540::DEBUG::2012-10-30 09:56:10,192::vmChannels::144::vds::(register) Add fileno 18 to listener's channels. Thread-1542::DEBUG::2012-10-30 09:56:10,192::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283' is free. Now locking as 'shared' (1 active user) Thread-1542::DEBUG::2012-10-30 09:56:10,193::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283`ReqID=`057d2200-a704-4de4-a45b-2771d72f30bb`::Granted request Thread-1542::DEBUG::2012-10-30 09:56:10,193::task::817::TaskManager.Task::(resourceAcquired) Task=`6a004d5d-63a9-4ffb-a887-8f7d5c6179c7`::_resourcesAcquired: Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283 (shared) Thread-1542::DEBUG::2012-10-30 09:56:10,193::task::978::TaskManager.Task::(_decref) Task=`6a004d5d-63a9-4ffb-a887-8f7d5c6179c7`::ref 1 aborting False Thread-1542::DEBUG::2012-10-30 09:56:10,195::fileVolume::535::Storage.Volume::(validateVolumePath) validate path for 12413fe4-a694-439b-95d8-40d5a576dada Thread-1540::WARNING::2012-10-30 09:56:10,196::libvirtvm::1547::vm.Vm::(_readPauseCode) vmId=`4abdba0d-aa1f-48f1-8160-3cde63165057`::_readPauseCode unsupported by libvirt vm Thread-1542::DEBUG::2012-10-30 09:56:10,199::fileVolume::535::Storage.Volume::(validateVolumePath) validate path for 12413fe4-a694-439b-95d8-40d5a576dada Thread-1542::INFO::2012-10-30 09:56:10,200::logUtils::39::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '0', 'apparentsize': '8589934592'} Thread-1542::DEBUG::2012-10-30 09:56:10,200::task::1172::TaskManager.Task::(prepare) Task=`6a004d5d-63a9-4ffb-a887-8f7d5c6179c7`::finished: {'truesize': '0', 'apparentsize': '8589934592'} Thread-1542::DEBUG::2012-10-30 09:56:10,201::task::588::TaskManager.Task::(_updateState) Task=`6a004d5d-63a9-4ffb-a887-8f7d5c6179c7`::moving from state preparing -> state finished Thread-1542::DEBUG::2012-10-30 09:56:10,201::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283': < ResourceRef 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283', isValid: 'True' obj: 'None'>} Thread-1542::DEBUG::2012-10-30 09:56:10,201::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-1542::DEBUG::2012-10-30 09:56:10,201::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283' Thread-1542::DEBUG::2012-10-30 09:56:10,202::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283' (0 active users) Thread-1542::DEBUG::2012-10-30 09:56:10,202::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283' is free, finding out if anyone is waiting for it. Thread-1542::DEBUG::2012-10-30 09:56:10,203::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283', Clearing records. Thread-1542::DEBUG::2012-10-30 09:56:10,203::task::978::TaskManager.Task::(_decref) Task=`6a004d5d-63a9-4ffb-a887-8f7d5c6179c7`::ref 0 aborting False Thread-1540::DEBUG::2012-10-30 09:56:10,206::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /usr/sbin/service ksmtuned retune' (cwd None) Thread-1540::DEBUG::2012-10-30 09:56:10,241::__init__::1249::Storage.Misc.excCmd::(_log) FAILED: <err> = "Redirecting to /bin/systemctl retune ksmtuned.service\nUnknown operation 'retune'.\n"; <rc> = 1 Thread-1540::DEBUG::2012-10-30 09:56:10,242::vm::580::vm.Vm::(_startUnde rlyingVm) vmId=`4abdba0d-aa1f-48f1-8160-3cde63165057`::_ongoingCreations released VM Channels Listener::DEBUG::2012-10-30 09:56:10,376::vmChannels::71::vds::(_do_add_channels) fileno 18 was added to unconnected channels. VM Channels Listener::DEBUG::2012-10-30 09:56:10,376::vmChannels::103::vds::(_handle_unconnected) Trying to connect fileno 18. VM Channels Listener::DEBUG::2012-10-30 09:56:10,376::guestIF::81::vm.Vm::(_connect) vmId=`4abdba0d-aa1f-48f1-8160-3cde63165057`::Attempting connection to /var/lib/libvirt/qemu/channels/bsdlinux04vm.com.redhat.rhevm.vdsm VM Channels Listener::DEBUG::2012-10-30 09:56:10,377::guestIF::83::vm.Vm::(_connect) vmId=`4abdba0d-aa1f-48f1-8160-3cde63165057`::Connected to /var/lib/libvirt/qemu/channels/bsdlinux04vm.com.redhat.rhevm.vdsm VM Channels Listener::DEBUG::2012-10-30 09:56:10,377::vmChannels::106::vds::(_handle_unconnected) Connect fileno 18 was succeed. Thread-1543::DEBUG::2012-10-30 09:56:14,759::BindingXMLRPC::156::vds::(wrapper) [192.168.1.10] Thread-1543::DEBUG::2012-10-30 09:56:14,760::task::588::TaskManager.Task::(_updateState) Task=`3379e8b3-bf70-49d0-b643-0bb17de93846`::moving from state init -> state preparing Thread-1543::INFO::2012-10-30 09:56:14,760::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='640fa36c-1da8-11e2-86f7-1078d2e9dece', options=None) Thread-1543::INFO::2012-10-30 09:56:14,761::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 1}} Thread-1543::DEBUG::2012-10-30 09:56:14,761::task::1172::TaskManager.Task::(prepare) Task=`3379e8b3-bf70-49d0-b643-0bb17de93846`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 1}} Thread-1543::DEBUG::2012-10-30 09:56:14,761::task::588::TaskManager.Task::(_updateState) Task=`3379e8b3-bf70-49d0-b643-0bb17de93846`::moving from state preparing -> state finished Thread-1543::DEBUG::2012-10-30 09:56:14,761::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-1543::DEBUG::2012-10-30 09:56:14,762::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-1543::DEBUG::2012-10-30 09:56:14,762::task::978::TaskManager.Task::(_decref) Task=`3379e8b3-bf70-49d0-b643-0bb17de93846`::ref 0 aborting False Thread-1544::DEBUG::2012-10-30 09:56:14,781::BindingXMLRPC::156::vds::(wrapper) [192.168.1.10] Thread-1544::DEBUG::2012-10-30 09:56:14,782::task::588::TaskManager.Task::(_updateState) Task=`f7a0fd20-fddb-48f7-832e-ed230b49d4f0`::moving from state init -> state preparing Thread-1544::INFO::2012-10-30 09:56:14,782::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='640fa36c-1da8-11e2-86f7-1078d2e9dece', options=None) Thread-1544::DEBUG::2012-10-30 09:56:14,782::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece`ReqID=`7e21374b-d582-451f-b37a-ee1ea2f206f1`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource' Thread-1544::DEBUG::2012-10-30 09:56:14,783::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece' for lock type 'shared' Thread-1544::DEBUG::2012-10-30 09:56:14,783::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece' is free. Now locking as 'shared' (1 active user) Thread-1544::DEBUG::2012-10-30 09:56:14,783::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece`ReqID=`7e21374b-d582-451f-b37a-ee1ea2f206f1`::Granted request Thread-1544::DEBUG::2012-10-30 09:56:14,784::task::817::TaskManager.Task::(resourceAcquired) Task=`f7a0fd20-fddb-48f7-832e-ed230b49d4f0`::_resourcesAcquired: Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece (shared) Thread-1544::DEBUG::2012-10-30 09:56:14,784::task::978::TaskManager.Task::(_decref) Task=`f7a0fd20-fddb-48f7-832e-ed230b49d4f0`::ref 1 aborting False Thread-1544::INFO::2012-10-30 09:56:14,793::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': 'e552b5fd-30fb-4e18-8bc4-26517f11a283', 'name': 'Default', 'version': '0', 'domains': '65f95655-5bbe-47e4-8d3a-6e2ffc5c7761:Active,e552b5fd-30fb-4e18-8bc4-26517f11a283:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/640fa36c-1da8-11e2-86f7-1078d2e9dece/65f95655-5bbe-47e4-8d3a-6e2ffc5c7761/images/11111111-1111-1111-1111-111111111111', 'type': 'SHAREDFS', 'master_ver': 1, 'lver': 1}, 'dominfo': {'65f95655-5bbe-47e4-8d3a-6e2ffc5c7761': {'status': 'Active', 'diskfree': '382827757568', 'alerts': [], 'disktotal': '424540110848'}, 'e552b5fd-30fb-4e18-8bc4-26517f11a283': {'status': 'Active', 'diskfree': '2099627163648', 'alerts': [], 'disktotal': '2212208836608'}}} Thread-1544::DEBUG::2012-10-30 09:56:14,793::task::1172::TaskManager.Task::(prepare) Task=`f7a0fd20-fddb-48f7-832e-ed230b49d4f0`::finished: {'info': {'spm_id': 1, 'master_uuid': 'e552b5fd-30fb-4e18-8bc4-26517f11a283', 'name': 'Default', 'version': '0', 'domains': '65f95655-5bbe-47e4-8d3a-6e2ffc5c7761:Active,e552b5fd-30fb-4e18-8bc4-26517f11a283:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/640fa36c-1da8-11e2-86f7-1078d2e9dece/65f95655-5bbe-47e4-8d3a-6e2ffc5c7761/images/11111111-1111-1111-1111-111111111111', 'type': 'SHAREDFS', 'master_ver': 1, 'lver': 1}, 'dominfo': {'65f95655-5bbe-47e4-8d3a-6e2ffc5c7761': {'status': 'Active', 'diskfree': '382827757568', 'alerts': [], 'disktotal': '424540110848'}, 'e552b5fd-30fb-4e18-8bc4-26517f11a283': {'status': 'Active', 'diskfree': '2099627163648', 'alerts': [], 'disktotal': '2212208836608'}}} Thread-1544::DEBUG::2012-10-30 09:56:14,794::task::588::TaskManager.Task::(_updateState) Task=`f7a0fd20-fddb-48f7-832e-ed230b49d4f0`::moving from state preparing -> state finished Thread-1544::DEBUG::2012-10-30 09:56:14,794::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece': < ResourceRef 'Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece', isValid: 'True' obj: 'None'>} Thread-1544::DEBUG::2012-10-30 09:56:14,794::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-1544::DEBUG::2012-10-30 09:56:14,794::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece' Thread-1544::DEBUG::2012-10-30 09:56:14,795::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece' (0 active users) Thread-1544::DEBUG::2012-10-30 09:56:14,795::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece' is free, finding out if anyone is waiting for it. Thread-1544::DEBUG::2012-10-30 09:56:14,795::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece', Clearing records. Thread-1544::DEBUG::2012-10-30 09:56:14,795::task::978::TaskManager.Task::(_decref) Task=`f7a0fd20-fddb-48f7-832e-ed230b49d4f0`::ref 0 aborting False Thread-1545::DEBUG::2012-10-30 09:56:24,820::BindingXMLRPC::156::vds::(wrapper) [192.168.1.10] Thread-1545::DEBUG::2012-10-30 09:56:24,820::task::588::TaskManager.Task::(_updateState) Task=`911438a8-fbf0-456f-b979-9e361bda85f2`::moving from state init -> state preparing Thread-1545::INFO::2012-10-30 09:56:24,821::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='640fa36c-1da8-11e2-86f7-1078d2e9dece', options=None) Thread-1545::INFO::2012-10-30 09:56:24,821::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 1}} Thread-1545::DEBUG::2012-10-30 09:56:24,821::task::1172::TaskManager.Task::(prepare) Task=`911438a8-fbf0-456f-b979-9e361bda85f2`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 1}} Thread-1545::DEBUG::2012-10-30 09:56:24,822::task::588::TaskManager.Task::(_updateState) Task=`911438a8-fbf0-456f-b979-9e361bda85f2`::moving from state preparing -> state finished Thread-1545::DEBUG::2012-10-30 09:56:24,822::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-1545::DEBUG::2012-10-30 09:56:24,822::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-1545::DEBUG::2012-10-30 09:56:24,822::task::978::TaskManager.Task::(_decref) Task=`911438a8-fbf0-456f-b979-9e361bda85f2`::ref 0 aborting False Thread-1546::DEBUG::2012-10-30 09:56:24,840::BindingXMLRPC::156::vds::(wrapper) [192.168.1.10] Thread-1546::DEBUG::2012-10-30 09:56:24,841::task::588::TaskManager.Task::(_updateState) Task=`fbf6f12b-58f8-45bf-b34f-5fa3ae93123c`::moving from state init -> state preparing Thread-1546::INFO::2012-10-30 09:56:24,841::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='640fa36c-1da8-11e2-86f7-1078d2e9dece', options=None) Thread-1546::DEBUG::2012-10-30 09:56:24,841::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece`ReqID=`c8c2813e-c44c-44f2-b1dd-0f797ecadce3`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource' Thread-1546::DEBUG::2012-10-30 09:56:24,842::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece' for lock type 'shared' Thread-1546::DEBUG::2012-10-30 09:56:24,842::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece' is free. Now locking as 'shared' (1 active user) Thread-1546::DEBUG::2012-10-30 09:56:24,842::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece`ReqID=`c8c2813e-c44c-44f2-b1dd-0f797ecadce3`::Granted request Thread-1546::DEBUG::2012-10-30 09:56:24,843::task::817::TaskManager.Task::(resourceAcquired) Task=`fbf6f12b-58f8-45bf-b34f-5fa3ae93123c`::_resourcesAcquired: Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece (shared) Thread-1546::DEBUG::2012-10-30 09:56:24,843::task::978::TaskManager.Task::(_decref) Task=`fbf6f12b-58f8-45bf-b34f-5fa3ae93123c`::ref 1 aborting False Thread-1546::INFO::2012-10-30 09:56:24,852::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': 'e552b5fd-30fb-4e18-8bc4-26517f11a283', 'name': 'Default', 'version': '0', 'domains': '65f95655-5bbe-47e4-8d3a-6e2ffc5c7761:Active,e552b5fd-30fb-4e18-8bc4-26517f11a283:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/640fa36c-1da8-11e2-86f7-1078d2e9dece/65f95655-5bbe-47e4-8d3a-6e2ffc5c7761/images/11111111-1111-1111-1111-111111111111', 'type': 'SHAREDFS', 'master_ver': 1, 'lver': 1}, 'dominfo': {'65f95655-5bbe-47e4-8d3a-6e2ffc5c7761': {'status': 'Active', 'diskfree': '382827757568', 'alerts': [], 'disktotal': '424540110848'}, 'e552b5fd-30fb-4e18-8bc4-26517f11a283': {'status': 'Active', 'diskfree': '2099627163648', 'alerts': [], 'disktotal': '2212208836608'}}} Thread-1546::DEBUG::2012-10-30 09:56:24,853::task::1172::TaskManager.Task::(prepare) Task=`fbf6f12b-58f8-45bf-b34f-5fa3ae93123c`::finished: {'info': {'spm_id': 1, 'master_uuid': 'e552b5fd-30fb-4e18-8bc4-26517f11a283', 'name': 'Default', 'version': '0', 'domains': '65f95655-5bbe-47e4-8d3a-6e2ffc5c7761:Active,e552b5fd-30fb-4e18-8bc4-26517f11a283:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/640fa36c-1da8-11e2-86f7-1078d2e9dece/65f95655-5bbe-47e4-8d3a-6e2ffc5c7761/images/11111111-1111-1111-1111-111111111111', 'type': 'SHAREDFS', 'master_ver': 1, 'lver': 1}, 'dominfo': {'65f95655-5bbe-47e4-8d3a-6e2ffc5c7761': {'status': 'Active', 'diskfree': '382827757568', 'alerts': [], 'disktotal': '424540110848'}, 'e552b5fd-30fb-4e18-8bc4-26517f11a283': {'status': 'Active', 'diskfree': '2099627163648', 'alerts': [], 'disktotal': '2212208836608'}}} Thread-1546::DEBUG::2012-10-30 09:56:24,853::task::588::TaskManager.Task::(_updateState) Task=`fbf6f12b-58f8-45bf-b34f-5fa3ae93123c`::moving from state preparing -> state finished Thread-1546::DEBUG::2012-10-30 09:56:24,853::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece': < ResourceRef 'Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece', isValid: 'True' obj: 'None'>} Thread-1546::DEBUG::2012-10-30 09:56:24,853::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-1546::DEBUG::2012-10-30 09:56:24,854::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece' Thread-1546::DEBUG::2012-10-30 09:56:24,854::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece' (0 active users) Thread-1546::DEBUG::2012-10-30 09:56:24,854::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece' is free, finding out if anyone is waiting for it. Thread-1546::DEBUG::2012-10-30 09:56:24,854::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece', Clearing records. Thread-1546::DEBUG::2012-10-30 09:56:24,855::task::978::TaskManager.Task::(_decref) Task=`fbf6f12b-58f8-45bf-b34f-5fa3ae93123c`::ref 0 aborting False Regards Daniel Rowe

On 10/30/2012 04:05 AM, Daniel Rowe wrote: please paste /var/log/engine/engine.log from the ovirt machine as well.
Hi
I have my oVirt setup to the point where I can add VM.
I am using Gluster and to get it to be able to add VMs I had to run "setsebool -P virt_use_fusefs=on" once I did this it seems to work fine for added VMs.
I have added a Fedora 17 vm, when I start the VM in oVirt, the management interface never see it as started, just always has the hour glass next to it.
If I do a PS on the node I can see the VM is indeed started and can see the qemu-kvm process for that VM.
There are no deny messages in audit.log on the node.
The message log on the node has this message: "VM start: vdsm vm.Vm WARNING vmId=`4abdba0d-aa1f-48f1-8160-3cde63165057`::_readPauseCode unsupported by libvirt vm".
Not sure if this is related.
The vdsm log when I click on the run VM:
Thread-1539::DEBUG::2012-10-30 09:56:09,203::BindingXMLRPC::859::vds::(wrapper) client [192.168.1.10]::call vmCreate with ({'custom': {'viodiskcache': 'writeback'}, 'keyboardLayout': 'en-us', 'kvmEnable': 'true', 'pitReinjection': 'false', 'acpiEnable': 'true', 'emulatedMachine': 'pc-0.14', 'vmId': '4abdba0d-aa1f-48f1-8160-3cde63165057', 'devices': [{'device': 'qxl', 'specParams': {'vram': '65536'}, 'type': 'video', 'deviceId': '25ada4cb-1108-491b-8d2c-c05cb353cc99'}, {'index': '2', 'iface': 'ide', 'bootOrder': '1', 'specParams': {'path': 'Fedora-17-x86_64-DVD.iso'}, 'readonly': 'true', 'deviceId': '1b62fc2d-88e5-42e0-9666-3de861a71c44', 'device': 'cdrom', 'path': '/rhev/data-center/640fa36c-1da8-11e2-86f7-1078d2e9dece/65f95655-5bbe-47e4-8d3a-6e2ffc5c7761/images/11111111-1111-1111-1111-111111111111/Fedora-17-x86_64-DVD.iso', 'type': 'disk'}, {'index': 0, 'iface': 'virtio', 'format': 'raw', 'type': 'disk', 'volumeID': '12413fe4-a694-439b-95d8-40d5a576dada', 'imageID': '025d5960-23db-4e07-98c8-4c9682155eb1', 'specParams': {}, 'readonly': 'false', 'domainID': 'e552b5fd-30fb-4e18-8bc4-26517f11a283', 'deviceId': '025d5960-23db-4e07-98c8-4c9682155eb1', 'poolID': '640fa36c-1da8-11e2-86f7-1078d2e9dece', 'device': 'disk', 'shared': 'false', 'propagateErrors': 'off', 'optional': 'false'}, {'nicModel': 'pv', 'macAddr': '00:1a:4a:70:83:00', 'network': 'ovirtmgmt', 'specParams': {}, 'deviceId': '80841d17-f758-46c8-84bc-0346072c4156', 'device': 'bridge', 'type': 'interface'}, {'device': 'memballoon', 'specParams': {'model': 'virtio'}, 'type': 'balloon', 'deviceId': '09f59ef5-b17f-49ea-99e6-8ee7bcca64a1'}], 'smp': '2', 'vmType': 'kvm', 'timeOffset': '0', 'memSize': 1024, 'spiceSslCipherSuite': 'DEFAULT', 'cpuType': 'Conroe', 'spiceSecureChannels': 'smain,sinputs,scursor,splayback,srecord,sdisplay', 'smpCoresPerSocket': '2', 'vmName': 'bsdlinux04vm', 'display': 'qxl', 'transparentHugePages': 'true', 'nice': '0'},) {} flowID [8a5456c] Thread-1539::INFO::2012-10-30 09:56:09,203::API::601::vds::(_getNetworkIp) network None: using 0 Thread-1539::INFO::2012-10-30 09:56:09,204::API::228::vds::(create) vmContainerLock acquired by vm 4abdba0d-aa1f-48f1-8160-3cde63165057 Thread-1540::DEBUG::2012-10-30 09:56:09,207::vm::564::vm.Vm::(_startUnderlyingVm) vmId=`4abdba0d-aa1f-48f1-8160-3cde63165057`::Start Thread-1539::DEBUG::2012-10-30 09:56:09,207::API::244::vds::(create) Total desktops after creation of 4abdba0d-aa1f-48f1-8160-3cde63165057 is 1 Thread-1539::DEBUG::2012-10-30 09:56:09,208::BindingXMLRPC::865::vds::(wrapper) return vmCreate with {'status': {'message': 'Done', 'code': 0}, 'vmList': {'status': 'WaitForLaunch', 'acpiEnable': 'true', 'emulatedMachine': 'pc-0.14', 'vmId': '4abdba0d-aa1f-48f1-8160-3cde63165057', 'pid': '0', 'timeOffset': '0', 'displayPort': '-1', 'displaySecurePort': '-1', 'spiceSslCipherSuite': 'DEFAULT', 'cpuType': 'Conroe', 'custom': {'viodiskcache': 'writeback'}, 'clientIp': '', 'nicModel': 'rtl8139,pv', 'keyboardLayout': 'en-us', 'kvmEnable': 'true', 'pitReinjection': 'false', 'transparentHugePages': 'true', 'devices': [{'device': 'qxl', 'specParams': {'vram': '65536'}, 'type': 'video', 'deviceId': '25ada4cb-1108-491b-8d2c-c05cb353cc99'}, {'index': '2', 'iface': 'ide', 'bootOrder': '1', 'specParams': {'path': 'Fedora-17-x86_64-DVD.iso'}, 'readonly': 'true', 'deviceId': '1b62fc2d-88e5-42e0-9666-3de861a71c44', 'device': 'cdrom', 'path': '/rhev/data-center/640fa36c-1da8-11e2-86f7-1078d2e9dece/65f95655-5bbe-47e4-8d3a-6e2ffc5c7761/images/11111111-1111-1111-1111-111111111111/Fedora-17-x86_64-DVD.iso', 'type': 'disk'}, {'index': 0, 'iface': 'virtio', 'format': 'raw', 'type': 'disk', 'volumeID': '12413fe4-a694-439b-95d8-40d5a576dada', 'imageID': '025d5960-23db-4e07-98c8-4c9682155eb1', 'specParams': {}, 'readonly': 'false', 'domainID': 'e552b5fd-30fb-4e18-8bc4-26517f11a283', 'deviceId': '025d5960-23db-4e07-98c8-4c9682155eb1', 'poolID': '640fa36c-1da8-11e2-86f7-1078d2e9dece', 'device': 'disk', 'shared': 'false', 'propagateErrors': 'off', 'optional': 'false'}, {'nicModel': 'pv', 'macAddr': '00:1a:4a:70:83:00', 'network': 'ovirtmgmt', 'specParams': {}, 'deviceId': '80841d17-f758-46c8-84bc-0346072c4156', 'device': 'bridge', 'type': 'interface'}, {'device': 'memballoon', 'specParams': {'model': 'virtio'}, 'type': 'balloon', 'deviceId': '09f59ef5-b17f-49ea-99e6-8ee7bcca64a1'}], 'smp': '2', 'vmType': 'kvm', 'memSize': 1024, 'displayIp': '0', 'spiceSecureChannels': 'smain,sinputs,scursor,splayback,srecord,sdisplay', 'smpCoresPerSocket': '2', 'vmName': 'bsdlinux04vm', 'display': 'qxl', 'nice': '0'}} Thread-1540::DEBUG::2012-10-30 09:56:09,208::vm::568::vm.Vm::(_startUnderlyingVm) vmId=`4abdba0d-aa1f-48f1-8160-3cde63165057`::_ongoingCreations acquired Thread-1540::INFO::2012-10-30 09:56:09,210::libvirtvm::1285::vm.Vm::(_run) vmId=`4abdba0d-aa1f-48f1-8160-3cde63165057`::VM wrapper has started Thread-1540::DEBUG::2012-10-30 09:56:09,211::task::588::TaskManager.Task::(_updateState) Task=`f91ddc64-360b-4f33-bb53-9c6436a6a6d4`::moving from state init -> state preparing Thread-1540::INFO::2012-10-30 09:56:09,211::logUtils::37::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='e552b5fd-30fb-4e18-8bc4-26517f11a283', spUUID='640fa36c-1da8-11e2-86f7-1078d2e9dece', imgUUID='025d5960-23db-4e07-98c8-4c9682155eb1', volUUID='12413fe4-a694-439b-95d8-40d5a576dada', options=None) Thread-1540::DEBUG::2012-10-30 09:56:09,212::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283`ReqID=`a4d63aa4-f9af-48c3-b57f-68149d3ea523`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource' Thread-1540::DEBUG::2012-10-30 09:56:09,212::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283' for lock type 'shared' Thread-1540::DEBUG::2012-10-30 09:56:09,212::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283' is free. Now locking as 'shared' (1 active user) Thread-1540::DEBUG::2012-10-30 09:56:09,213::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283`ReqID=`a4d63aa4-f9af-48c3-b57f-68149d3ea523`::Granted request Thread-1540::DEBUG::2012-10-30 09:56:09,213::task::817::TaskManager.Task::(resourceAcquired) Task=`f91ddc64-360b-4f33-bb53-9c6436a6a6d4`::_resourcesAcquired: Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283 (shared) Thread-1540::DEBUG::2012-10-30 09:56:09,213::task::978::TaskManager.Task::(_decref) Task=`f91ddc64-360b-4f33-bb53-9c6436a6a6d4`::ref 1 aborting False Thread-1540::DEBUG::2012-10-30 09:56:09,216::fileVolume::535::Storage.Volume::(validateVolumePath) validate path for 12413fe4-a694-439b-95d8-40d5a576dada Thread-1540::DEBUG::2012-10-30 09:56:09,220::fileVolume::535::Storage.Volume::(validateVolumePath) validate path for 12413fe4-a694-439b-95d8-40d5a576dada Thread-1540::INFO::2012-10-30 09:56:09,221::logUtils::39::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '0', 'apparentsize': '8589934592'} Thread-1540::DEBUG::2012-10-30 09:56:09,221::task::1172::TaskManager.Task::(prepare) Task=`f91ddc64-360b-4f33-bb53-9c6436a6a6d4`::finished: {'truesize': '0', 'apparentsize': '8589934592'} Thread-1540::DEBUG::2012-10-30 09:56:09,222::task::588::TaskManager.Task::(_updateState) Task=`f91ddc64-360b-4f33-bb53-9c6436a6a6d4`::moving from state preparing -> state finished Thread-1540::DEBUG::2012-10-30 09:56:09,222::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283': < ResourceRef 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283', isValid: 'True' obj: 'None'>} Thread-1540::DEBUG::2012-10-30 09:56:09,222::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-1540::DEBUG::2012-10-30 09:56:09,222::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283' Thread-1540::DEBUG::2012-10-30 09:56:09,223::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283' (0 active users) Thread-1540::DEBUG::2012-10-30 09:56:09,223::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283' is free, finding out if anyone is waiting for it. Thread-1540::DEBUG::2012-10-30 09:56:09,223::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283', Clearing records. Thread-1540::DEBUG::2012-10-30 09:56:09,223::task::978::TaskManager.Task::(_decref) Task=`f91ddc64-360b-4f33-bb53-9c6436a6a6d4`::ref 0 aborting False Thread-1540::INFO::2012-10-30 09:56:09,224::clientIF::274::vds::(prepareVolumePath) prepared volume path: /rhev/data-center/640fa36c-1da8-11e2-86f7-1078d2e9dece/65f95655-5bbe-47e4-8d3a-6e2ffc5c7761/images/11111111-1111-1111-1111-111111111111/Fedora-17-x86_64-DVD.iso Thread-1540::DEBUG::2012-10-30 09:56:09,224::task::588::TaskManager.Task::(_updateState) Task=`c1701ef5-96d8-4036-a5cb-7a285152d84f`::moving from state init -> state preparing Thread-1540::INFO::2012-10-30 09:56:09,224::logUtils::37::dispatcher::(wrapper) Run and protect: prepareImage(sdUUID='e552b5fd-30fb-4e18-8bc4-26517f11a283', spUUID='640fa36c-1da8-11e2-86f7-1078d2e9dece', imgUUID='025d5960-23db-4e07-98c8-4c9682155eb1', volUUID='12413fe4-a694-439b-95d8-40d5a576dada') Thread-1540::DEBUG::2012-10-30 09:56:09,225::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283`ReqID=`1fd9533e-6b8a-458d-a4d2-001f0cc93ac2`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource' Thread-1540::DEBUG::2012-10-30 09:56:09,225::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283' for lock type 'shared' Thread-1540::DEBUG::2012-10-30 09:56:09,225::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283' is free. Now locking as 'shared' (1 active user) Thread-1540::DEBUG::2012-10-30 09:56:09,225::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283`ReqID=`1fd9533e-6b8a-458d-a4d2-001f0cc93ac2`::Granted request Thread-1540::DEBUG::2012-10-30 09:56:09,226::task::817::TaskManager.Task::(resourceAcquired) Task=`c1701ef5-96d8-4036-a5cb-7a285152d84f`::_resourcesAcquired: Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283 (shared) Thread-1540::DEBUG::2012-10-30 09:56:09,226::task::978::TaskManager.Task::(_decref) Task=`c1701ef5-96d8-4036-a5cb-7a285152d84f`::ref 1 aborting False Thread-1540::DEBUG::2012-10-30 09:56:09,227::fileVolume::535::Storage.Volume::(validateVolumePath) validate path for 12413fe4-a694-439b-95d8-40d5a576dada Thread-1540::INFO::2012-10-30 09:56:09,234::image::357::Storage.Image::(getChain) sdUUID=e552b5fd-30fb-4e18-8bc4-26517f11a283 imgUUID=025d5960-23db-4e07-98c8-4c9682155eb1 chain=[<storage.fileVolume.FileVolume instance at 0x7f82442cb0e0>] Thread-1540::INFO::2012-10-30 09:56:09,237::logUtils::39::dispatcher::(wrapper) Run and protect: prepareImage, Return response: {'path': '/rhev/data-center/640fa36c-1da8-11e2-86f7-1078d2e9dece/e552b5fd-30fb-4e18-8bc4-26517f11a283/images/025d5960-23db-4e07-98c8-4c9682155eb1/12413fe4-a694-439b-95d8-40d5a576dada', 'chain': [{'path': '/rhev/data-center/640fa36c-1da8-11e2-86f7-1078d2e9dece/e552b5fd-30fb-4e18-8bc4-26517f11a283/images/025d5960-23db-4e07-98c8-4c9682155eb1/12413fe4-a694-439b-95d8-40d5a576dada', 'domainID': 'e552b5fd-30fb-4e18-8bc4-26517f11a283', 'volumeID': '12413fe4-a694-439b-95d8-40d5a576dada', 'imageID': '025d5960-23db-4e07-98c8-4c9682155eb1'}]} Thread-1540::DEBUG::2012-10-30 09:56:09,237::task::1172::TaskManager.Task::(prepare) Task=`c1701ef5-96d8-4036-a5cb-7a285152d84f`::finished: {'path': '/rhev/data-center/640fa36c-1da8-11e2-86f7-1078d2e9dece/e552b5fd-30fb-4e18-8bc4-26517f11a283/images/025d5960-23db-4e07-98c8-4c9682155eb1/12413fe4-a694-439b-95d8-40d5a576dada', 'chain': [{'path': '/rhev/data-center/640fa36c-1da8-11e2-86f7-1078d2e9dece/e552b5fd-30fb-4e18-8bc4-26517f11a283/images/025d5960-23db-4e07-98c8-4c9682155eb1/12413fe4-a694-439b-95d8-40d5a576dada', 'domainID': 'e552b5fd-30fb-4e18-8bc4-26517f11a283', 'volumeID': '12413fe4-a694-439b-95d8-40d5a576dada', 'imageID': '025d5960-23db-4e07-98c8-4c9682155eb1'}]} Thread-1540::DEBUG::2012-10-30 09:56:09,237::task::588::TaskManager.Task::(_updateState) Task=`c1701ef5-96d8-4036-a5cb-7a285152d84f`::moving from state preparing -> state finished Thread-1540::DEBUG::2012-10-30 09:56:09,237::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283': < ResourceRef 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283', isValid: 'True' obj: 'None'>} Thread-1540::DEBUG::2012-10-30 09:56:09,237::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-1540::DEBUG::2012-10-30 09:56:09,238::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283' Thread-1540::DEBUG::2012-10-30 09:56:09,238::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283' (0 active users) Thread-1540::DEBUG::2012-10-30 09:56:09,238::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283' is free, finding out if anyone is waiting for it. Thread-1540::DEBUG::2012-10-30 09:56:09,238::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283', Clearing records. Thread-1540::DEBUG::2012-10-30 09:56:09,239::task::978::TaskManager.Task::(_decref) Task=`c1701ef5-96d8-4036-a5cb-7a285152d84f`::ref 0 aborting False Thread-1540::INFO::2012-10-30 09:56:09,239::clientIF::274::vds::(prepareVolumePath) prepared volume path: /rhev/data-center/640fa36c-1da8-11e2-86f7-1078d2e9dece/e552b5fd-30fb-4e18-8bc4-26517f11a283/images/025d5960-23db-4e07-98c8-4c9682155eb1/12413fe4-a694-439b-95d8-40d5a576dada Thread-1540::DEBUG::2012-10-30 09:56:09,249::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/libexec/vdsm/hooks/before_vm_start/50_hugepages' (cwd None) Thread-1540::DEBUG::2012-10-30 09:56:09,375::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0 Thread-1540::INFO::2012-10-30 09:56:09,376::hooks::72::root::(_runHooksDir) Thread-1540::DEBUG::2012-10-30 09:56:09,376::libvirtvm::1338::vm.Vm::(_run) vmId=`4abdba0d-aa1f-48f1-8160-3cde63165057`::<?xml version="1.0" encoding="utf-8"?> <domain type="kvm"> <name>bsdlinux04vm</name> <uuid>4abdba0d-aa1f-48f1-8160-3cde63165057</uuid> <memory>1048576</memory> <currentMemory>1048576</currentMemory> <vcpu>2</vcpu> <devices> <channel type="unix"> <target name="com.redhat.rhevm.vdsm" type="virtio"/> <source mode="bind" path="/var/lib/libvirt/qemu/channels/bsdlinux04vm.com.redhat.rhevm.vdsm"/> </channel> <input bus="ps2" type="mouse"/> <channel type="spicevmc"> <target name="com.redhat.spice.0" type="virtio"/> </channel> <graphics autoport="yes" keymap="en-us" 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"/> </graphics> <console type="pty"> <target port="0" type="virtio"/> </console> <video> <model heads="1" type="qxl" vram="65536"/> </video> <interface type="bridge"> <mac address="00:1a:4a:70:83:00"/> <model type="virtio"/> <source bridge="ovirtmgmt"/> </interface> <memballoon model="virtio"/> <disk device="cdrom" snapshot="no" type="file"> <source file="/rhev/data-center/640fa36c-1da8-11e2-86f7-1078d2e9dece/65f95655-5bbe-47e4-8d3a-6e2ffc5c7761/images/11111111-1111-1111-1111-111111111111/Fedora-17-x86_64-DVD.iso" startupPolicy="optional"/> <target bus="ide" dev="hdc"/> <readonly/> <serial></serial> <boot order="1"/> </disk> <disk device="disk" snapshot="no" type="file"> <source file="/rhev/data-center/640fa36c-1da8-11e2-86f7-1078d2e9dece/e552b5fd-30fb-4e18-8bc4-26517f11a283/images/025d5960-23db-4e07-98c8-4c9682155eb1/12413fe4-a694-439b-95d8-40d5a576dada"/> <target bus="virtio" dev="vda"/> <serial>025d5960-23db-4e07-98c8-4c9682155eb1</serial> <driver cache="writeback" error_policy="stop" io="threads" name="qemu" type="raw"/> </disk> </devices> <os> <type arch="x86_64" machine="pc-0.14">hvm</type> <smbios mode="sysinfo"/> </os> <sysinfo type="smbios"> <system> <entry name="manufacturer">Red Hat</entry> <entry name="product">RHEV Hypervisor</entry> <entry name="version">17-1</entry> <entry name="serial">4C4C4544-0059-4810-8034-B7C04F463253_d4:ae:52:a3:1c:1e</entry> <entry name="uuid">4abdba0d-aa1f-48f1-8160-3cde63165057</entry> </system> </sysinfo> <clock adjustment="0" offset="variable"> <timer name="rtc" tickpolicy="catchup"/> </clock> <features> <acpi/> </features> <cpu match="exact"> <model>Conroe</model> <topology cores="2" sockets="1" threads="1"/> </cpu> </domain>
libvirtEventLoop::DEBUG::2012-10-30 09:56:10,075::libvirtvm::2409::vm.Vm::(_onLibvirtLifecycleEvent) vmId=`4abdba0d-aa1f-48f1-8160-3cde63165057`::event Started detail 0 opaque None Thread-1540::DEBUG::2012-10-30 09:56:10,188::utils::329::vm.Vm::(start) vmId=`4abdba0d-aa1f-48f1-8160-3cde63165057`::Start statistics collection Thread-1542::DEBUG::2012-10-30 09:56:10,188::utils::358::vm.Vm::(run) vmId=`4abdba0d-aa1f-48f1-8160-3cde63165057`::Stats thread started Thread-1542::DEBUG::2012-10-30 09:56:10,189::task::588::TaskManager.Task::( _updateState) Task=`6a004d5d-63a9-4ffb-a887-8f7d5c6179c7`::moving from state init -> state preparing Thread-1542::INFO::2012-10-30 09:56:10,190::logUtils::37::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='e552b5fd-30fb-4e18-8bc4-26517f11a283', spUUID='640fa36c-1da8-11e2-86f7-1078d2e9dece', imgUUID='025d5960-23db-4e07-98c8-4c9682155eb1', volUUID='12413fe4-a694-439b-95d8-40d5a576dada', options=None) Thread-1542::DEBUG::2012-10-30 09:56:10,191::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283`ReqID=`057d2200-a704-4de4-a45b-2771d72f30bb`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource' Thread-1542::DEBUG::2012-10-30 09:56:10,191::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283' for lock type 'shared' Thread-1540::DEBUG::2012-10-30 09:56:10,192::vmChannels::144::vds::(register) Add fileno 18 to listener's channels. Thread-1542::DEBUG::2012-10-30 09:56:10,192::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283' is free. Now locking as 'shared' (1 active user) Thread-1542::DEBUG::2012-10-30 09:56:10,193::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283`ReqID=`057d2200-a704-4de4-a45b-2771d72f30bb`::Granted request Thread-1542::DEBUG::2012-10-30 09:56:10,193::task::817::TaskManager.Task::(resourceAcquired) Task=`6a004d5d-63a9-4ffb-a887-8f7d5c6179c7`::_resourcesAcquired: Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283 (shared) Thread-1542::DEBUG::2012-10-30 09:56:10,193::task::978::TaskManager.Task::(_decref) Task=`6a004d5d-63a9-4ffb-a887-8f7d5c6179c7`::ref 1 aborting False Thread-1542::DEBUG::2012-10-30 09:56:10,195::fileVolume::535::Storage.Volume::(validateVolumePath) validate path for 12413fe4-a694-439b-95d8-40d5a576dada Thread-1540::WARNING::2012-10-30 09:56:10,196::libvirtvm::1547::vm.Vm::(_readPauseCode) vmId=`4abdba0d-aa1f-48f1-8160-3cde63165057`::_readPauseCode unsupported by libvirt vm Thread-1542::DEBUG::2012-10-30 09:56:10,199::fileVolume::535::Storage.Volume::(validateVolumePath) validate path for 12413fe4-a694-439b-95d8-40d5a576dada Thread-1542::INFO::2012-10-30 09:56:10,200::logUtils::39::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '0', 'apparentsize': '8589934592'} Thread-1542::DEBUG::2012-10-30 09:56:10,200::task::1172::TaskManager.Task::(prepare) Task=`6a004d5d-63a9-4ffb-a887-8f7d5c6179c7`::finished: {'truesize': '0', 'apparentsize': '8589934592'} Thread-1542::DEBUG::2012-10-30 09:56:10,201::task::588::TaskManager.Task::(_updateState) Task=`6a004d5d-63a9-4ffb-a887-8f7d5c6179c7`::moving from state preparing -> state finished Thread-1542::DEBUG::2012-10-30 09:56:10,201::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283': < ResourceRef 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283', isValid: 'True' obj: 'None'>} Thread-1542::DEBUG::2012-10-30 09:56:10,201::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-1542::DEBUG::2012-10-30 09:56:10,201::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283' Thread-1542::DEBUG::2012-10-30 09:56:10,202::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283' (0 active users) Thread-1542::DEBUG::2012-10-30 09:56:10,202::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283' is free, finding out if anyone is waiting for it. Thread-1542::DEBUG::2012-10-30 09:56:10,203::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283', Clearing records. Thread-1542::DEBUG::2012-10-30 09:56:10,203::task::978::TaskManager.Task::(_decref) Task=`6a004d5d-63a9-4ffb-a887-8f7d5c6179c7`::ref 0 aborting False Thread-1540::DEBUG::2012-10-30 09:56:10,206::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /usr/sbin/service ksmtuned retune' (cwd None) Thread-1540::DEBUG::2012-10-30 09:56:10,241::__init__::1249::Storage.Misc.excCmd::(_log) FAILED: <err> = "Redirecting to /bin/systemctl retune ksmtuned.service\nUnknown operation 'retune'.\n"; <rc> = 1 Thread-1540::DEBUG::2012-10-30 09:56:10,242::vm::580::vm.Vm::(_startUnde rlyingVm) vmId=`4abdba0d-aa1f-48f1-8160-3cde63165057`::_ongoingCreations released VM Channels Listener::DEBUG::2012-10-30 09:56:10,376::vmChannels::71::vds::(_do_add_channels) fileno 18 was added to unconnected channels. VM Channels Listener::DEBUG::2012-10-30 09:56:10,376::vmChannels::103::vds::(_handle_unconnected) Trying to connect fileno 18. VM Channels Listener::DEBUG::2012-10-30 09:56:10,376::guestIF::81::vm.Vm::(_connect) vmId=`4abdba0d-aa1f-48f1-8160-3cde63165057`::Attempting connection to /var/lib/libvirt/qemu/channels/bsdlinux04vm.com.redhat.rhevm.vdsm VM Channels Listener::DEBUG::2012-10-30 09:56:10,377::guestIF::83::vm.Vm::(_connect) vmId=`4abdba0d-aa1f-48f1-8160-3cde63165057`::Connected to /var/lib/libvirt/qemu/channels/bsdlinux04vm.com.redhat.rhevm.vdsm VM Channels Listener::DEBUG::2012-10-30 09:56:10,377::vmChannels::106::vds::(_handle_unconnected) Connect fileno 18 was succeed. Thread-1543::DEBUG::2012-10-30 09:56:14,759::BindingXMLRPC::156::vds::(wrapper) [192.168.1.10] Thread-1543::DEBUG::2012-10-30 09:56:14,760::task::588::TaskManager.Task::(_updateState) Task=`3379e8b3-bf70-49d0-b643-0bb17de93846`::moving from state init -> state preparing Thread-1543::INFO::2012-10-30 09:56:14,760::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='640fa36c-1da8-11e2-86f7-1078d2e9dece', options=None) Thread-1543::INFO::2012-10-30 09:56:14,761::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 1}} Thread-1543::DEBUG::2012-10-30 09:56:14,761::task::1172::TaskManager.Task::(prepare) Task=`3379e8b3-bf70-49d0-b643-0bb17de93846`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 1}} Thread-1543::DEBUG::2012-10-30 09:56:14,761::task::588::TaskManager.Task::(_updateState) Task=`3379e8b3-bf70-49d0-b643-0bb17de93846`::moving from state preparing -> state finished Thread-1543::DEBUG::2012-10-30 09:56:14,761::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-1543::DEBUG::2012-10-30 09:56:14,762::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-1543::DEBUG::2012-10-30 09:56:14,762::task::978::TaskManager.Task::(_decref) Task=`3379e8b3-bf70-49d0-b643-0bb17de93846`::ref 0 aborting False Thread-1544::DEBUG::2012-10-30 09:56:14,781::BindingXMLRPC::156::vds::(wrapper) [192.168.1.10] Thread-1544::DEBUG::2012-10-30 09:56:14,782::task::588::TaskManager.Task::(_updateState) Task=`f7a0fd20-fddb-48f7-832e-ed230b49d4f0`::moving from state init -> state preparing Thread-1544::INFO::2012-10-30 09:56:14,782::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='640fa36c-1da8-11e2-86f7-1078d2e9dece', options=None) Thread-1544::DEBUG::2012-10-30 09:56:14,782::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece`ReqID=`7e21374b-d582-451f-b37a-ee1ea2f206f1`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource' Thread-1544::DEBUG::2012-10-30 09:56:14,783::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece' for lock type 'shared' Thread-1544::DEBUG::2012-10-30 09:56:14,783::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece' is free. Now locking as 'shared' (1 active user) Thread-1544::DEBUG::2012-10-30 09:56:14,783::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece`ReqID=`7e21374b-d582-451f-b37a-ee1ea2f206f1`::Granted request Thread-1544::DEBUG::2012-10-30 09:56:14,784::task::817::TaskManager.Task::(resourceAcquired) Task=`f7a0fd20-fddb-48f7-832e-ed230b49d4f0`::_resourcesAcquired: Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece (shared) Thread-1544::DEBUG::2012-10-30 09:56:14,784::task::978::TaskManager.Task::(_decref) Task=`f7a0fd20-fddb-48f7-832e-ed230b49d4f0`::ref 1 aborting False Thread-1544::INFO::2012-10-30 09:56:14,793::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': 'e552b5fd-30fb-4e18-8bc4-26517f11a283', 'name': 'Default', 'version': '0', 'domains': '65f95655-5bbe-47e4-8d3a-6e2ffc5c7761:Active,e552b5fd-30fb-4e18-8bc4-26517f11a283:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/640fa36c-1da8-11e2-86f7-1078d2e9dece/65f95655-5bbe-47e4-8d3a-6e2ffc5c7761/images/11111111-1111-1111-1111-111111111111', 'type': 'SHAREDFS', 'master_ver': 1, 'lver': 1}, 'dominfo': {'65f95655-5bbe-47e4-8d3a-6e2ffc5c7761': {'status': 'Active', 'diskfree': '382827757568', 'alerts': [], 'disktotal': '424540110848'}, 'e552b5fd-30fb-4e18-8bc4-26517f11a283': {'status': 'Active', 'diskfree': '2099627163648', 'alerts': [], 'disktotal': '2212208836608'}}} Thread-1544::DEBUG::2012-10-30 09:56:14,793::task::1172::TaskManager.Task::(prepare) Task=`f7a0fd20-fddb-48f7-832e-ed230b49d4f0`::finished: {'info': {'spm_id': 1, 'master_uuid': 'e552b5fd-30fb-4e18-8bc4-26517f11a283', 'name': 'Default', 'version': '0', 'domains': '65f95655-5bbe-47e4-8d3a-6e2ffc5c7761:Active,e552b5fd-30fb-4e18-8bc4-26517f11a283:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/640fa36c-1da8-11e2-86f7-1078d2e9dece/65f95655-5bbe-47e4-8d3a-6e2ffc5c7761/images/11111111-1111-1111-1111-111111111111', 'type': 'SHAREDFS', 'master_ver': 1, 'lver': 1}, 'dominfo': {'65f95655-5bbe-47e4-8d3a-6e2ffc5c7761': {'status': 'Active', 'diskfree': '382827757568', 'alerts': [], 'disktotal': '424540110848'}, 'e552b5fd-30fb-4e18-8bc4-26517f11a283': {'status': 'Active', 'diskfree': '2099627163648', 'alerts': [], 'disktotal': '2212208836608'}}} Thread-1544::DEBUG::2012-10-30 09:56:14,794::task::588::TaskManager.Task::(_updateState) Task=`f7a0fd20-fddb-48f7-832e-ed230b49d4f0`::moving from state preparing -> state finished Thread-1544::DEBUG::2012-10-30 09:56:14,794::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece': < ResourceRef 'Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece', isValid: 'True' obj: 'None'>} Thread-1544::DEBUG::2012-10-30 09:56:14,794::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-1544::DEBUG::2012-10-30 09:56:14,794::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece' Thread-1544::DEBUG::2012-10-30 09:56:14,795::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece' (0 active users) Thread-1544::DEBUG::2012-10-30 09:56:14,795::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece' is free, finding out if anyone is waiting for it. Thread-1544::DEBUG::2012-10-30 09:56:14,795::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece', Clearing records. Thread-1544::DEBUG::2012-10-30 09:56:14,795::task::978::TaskManager.Task::(_decref) Task=`f7a0fd20-fddb-48f7-832e-ed230b49d4f0`::ref 0 aborting False Thread-1545::DEBUG::2012-10-30 09:56:24,820::BindingXMLRPC::156::vds::(wrapper) [192.168.1.10] Thread-1545::DEBUG::2012-10-30 09:56:24,820::task::588::TaskManager.Task::(_updateState) Task=`911438a8-fbf0-456f-b979-9e361bda85f2`::moving from state init -> state preparing Thread-1545::INFO::2012-10-30 09:56:24,821::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='640fa36c-1da8-11e2-86f7-1078d2e9dece', options=None) Thread-1545::INFO::2012-10-30 09:56:24,821::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 1}} Thread-1545::DEBUG::2012-10-30 09:56:24,821::task::1172::TaskManager.Task::(prepare) Task=`911438a8-fbf0-456f-b979-9e361bda85f2`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 1}} Thread-1545::DEBUG::2012-10-30 09:56:24,822::task::588::TaskManager.Task::(_updateState) Task=`911438a8-fbf0-456f-b979-9e361bda85f2`::moving from state preparing -> state finished Thread-1545::DEBUG::2012-10-30 09:56:24,822::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-1545::DEBUG::2012-10-30 09:56:24,822::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-1545::DEBUG::2012-10-30 09:56:24,822::task::978::TaskManager.Task::(_decref) Task=`911438a8-fbf0-456f-b979-9e361bda85f2`::ref 0 aborting False Thread-1546::DEBUG::2012-10-30 09:56:24,840::BindingXMLRPC::156::vds::(wrapper) [192.168.1.10] Thread-1546::DEBUG::2012-10-30 09:56:24,841::task::588::TaskManager.Task::(_updateState) Task=`fbf6f12b-58f8-45bf-b34f-5fa3ae93123c`::moving from state init -> state preparing Thread-1546::INFO::2012-10-30 09:56:24,841::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='640fa36c-1da8-11e2-86f7-1078d2e9dece', options=None) Thread-1546::DEBUG::2012-10-30 09:56:24,841::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece`ReqID=`c8c2813e-c44c-44f2-b1dd-0f797ecadce3`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource' Thread-1546::DEBUG::2012-10-30 09:56:24,842::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece' for lock type 'shared' Thread-1546::DEBUG::2012-10-30 09:56:24,842::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece' is free. Now locking as 'shared' (1 active user) Thread-1546::DEBUG::2012-10-30 09:56:24,842::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece`ReqID=`c8c2813e-c44c-44f2-b1dd-0f797ecadce3`::Granted request Thread-1546::DEBUG::2012-10-30 09:56:24,843::task::817::TaskManager.Task::(resourceAcquired) Task=`fbf6f12b-58f8-45bf-b34f-5fa3ae93123c`::_resourcesAcquired: Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece (shared) Thread-1546::DEBUG::2012-10-30 09:56:24,843::task::978::TaskManager.Task::(_decref) Task=`fbf6f12b-58f8-45bf-b34f-5fa3ae93123c`::ref 1 aborting False Thread-1546::INFO::2012-10-30 09:56:24,852::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': 'e552b5fd-30fb-4e18-8bc4-26517f11a283', 'name': 'Default', 'version': '0', 'domains': '65f95655-5bbe-47e4-8d3a-6e2ffc5c7761:Active,e552b5fd-30fb-4e18-8bc4-26517f11a283:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/640fa36c-1da8-11e2-86f7-1078d2e9dece/65f95655-5bbe-47e4-8d3a-6e2ffc5c7761/images/11111111-1111-1111-1111-111111111111', 'type': 'SHAREDFS', 'master_ver': 1, 'lver': 1}, 'dominfo': {'65f95655-5bbe-47e4-8d3a-6e2ffc5c7761': {'status': 'Active', 'diskfree': '382827757568', 'alerts': [], 'disktotal': '424540110848'}, 'e552b5fd-30fb-4e18-8bc4-26517f11a283': {'status': 'Active', 'diskfree': '2099627163648', 'alerts': [], 'disktotal': '2212208836608'}}} Thread-1546::DEBUG::2012-10-30 09:56:24,853::task::1172::TaskManager.Task::(prepare) Task=`fbf6f12b-58f8-45bf-b34f-5fa3ae93123c`::finished: {'info': {'spm_id': 1, 'master_uuid': 'e552b5fd-30fb-4e18-8bc4-26517f11a283', 'name': 'Default', 'version': '0', 'domains': '65f95655-5bbe-47e4-8d3a-6e2ffc5c7761:Active,e552b5fd-30fb-4e18-8bc4-26517f11a283:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/640fa36c-1da8-11e2-86f7-1078d2e9dece/65f95655-5bbe-47e4-8d3a-6e2ffc5c7761/images/11111111-1111-1111-1111-111111111111', 'type': 'SHAREDFS', 'master_ver': 1, 'lver': 1}, 'dominfo': {'65f95655-5bbe-47e4-8d3a-6e2ffc5c7761': {'status': 'Active', 'diskfree': '382827757568', 'alerts': [], 'disktotal': '424540110848'}, 'e552b5fd-30fb-4e18-8bc4-26517f11a283': {'status': 'Active', 'diskfree': '2099627163648', 'alerts': [], 'disktotal': '2212208836608'}}} Thread-1546::DEBUG::2012-10-30 09:56:24,853::task::588::TaskManager.Task::(_updateState) Task=`fbf6f12b-58f8-45bf-b34f-5fa3ae93123c`::moving from state preparing -> state finished Thread-1546::DEBUG::2012-10-30 09:56:24,853::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece': < ResourceRef 'Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece', isValid: 'True' obj: 'None'>} Thread-1546::DEBUG::2012-10-30 09:56:24,853::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-1546::DEBUG::2012-10-30 09:56:24,854::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece' Thread-1546::DEBUG::2012-10-30 09:56:24,854::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece' (0 active users) Thread-1546::DEBUG::2012-10-30 09:56:24,854::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece' is free, finding out if anyone is waiting for it. Thread-1546::DEBUG::2012-10-30 09:56:24,854::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece', Clearing records. Thread-1546::DEBUG::2012-10-30 09:56:24,855::task::978::TaskManager.Task::(_decref) Task=`fbf6f12b-58f8-45bf-b34f-5fa3ae93123c`::ref 0 aborting False
Regards Daniel Rowe _______________________________________________ Users mailing list Users@ovirt.org http://lists.ovirt.org/mailman/listinfo/users

On 10/30/2012 08:40 AM, Roy Golan wrote:
On 10/30/2012 04:05 AM, Daniel Rowe wrote:
please paste /var/log/engine/engine.log from the ovirt machine as well.
and output of 'vdsClient -s 0 getAllVmStats' from vdsm node
Hi
I have my oVirt setup to the point where I can add VM.
I am using Gluster and to get it to be able to add VMs I had to run "setsebool -P virt_use_fusefs=on" once I did this it seems to work fine for added VMs.
I have added a Fedora 17 vm, when I start the VM in oVirt, the management interface never see it as started, just always has the hour glass next to it.
If I do a PS on the node I can see the VM is indeed started and can see the qemu-kvm process for that VM.
There are no deny messages in audit.log on the node.
The message log on the node has this message: "VM start: vdsm vm.Vm WARNING vmId=`4abdba0d-aa1f-48f1-8160-3cde63165057`::_readPauseCode unsupported by libvirt vm".
Not sure if this is related.
The vdsm log when I click on the run VM:
Thread-1539::DEBUG::2012-10-30 09:56:09,203::BindingXMLRPC::859::vds::(wrapper) client [192.168.1.10]::call vmCreate with ({'custom': {'viodiskcache': 'writeback'}, 'keyboardLayout': 'en-us', 'kvmEnable': 'true', 'pitReinjection': 'false', 'acpiEnable': 'true', 'emulatedMachine': 'pc-0.14', 'vmId': '4abdba0d-aa1f-48f1-8160-3cde63165057', 'devices': [{'device': 'qxl', 'specParams': {'vram': '65536'}, 'type': 'video', 'deviceId': '25ada4cb-1108-491b-8d2c-c05cb353cc99'}, {'index': '2', 'iface': 'ide', 'bootOrder': '1', 'specParams': {'path': 'Fedora-17-x86_64-DVD.iso'}, 'readonly': 'true', 'deviceId': '1b62fc2d-88e5-42e0-9666-3de861a71c44', 'device': 'cdrom', 'path': '/rhev/data-center/640fa36c-1da8-11e2-86f7-1078d2e9dece/65f95655-5bbe-47e4-8d3a-6e2ffc5c7761/images/11111111-1111-1111-1111-111111111111/Fedora-17-x86_64-DVD.iso',
'type': 'disk'}, {'index': 0, 'iface': 'virtio', 'format': 'raw', 'type': 'disk', 'volumeID': '12413fe4-a694-439b-95d8-40d5a576dada', 'imageID': '025d5960-23db-4e07-98c8-4c9682155eb1', 'specParams': {}, 'readonly': 'false', 'domainID': 'e552b5fd-30fb-4e18-8bc4-26517f11a283', 'deviceId': '025d5960-23db-4e07-98c8-4c9682155eb1', 'poolID': '640fa36c-1da8-11e2-86f7-1078d2e9dece', 'device': 'disk', 'shared': 'false', 'propagateErrors': 'off', 'optional': 'false'}, {'nicModel': 'pv', 'macAddr': '00:1a:4a:70:83:00', 'network': 'ovirtmgmt', 'specParams': {}, 'deviceId': '80841d17-f758-46c8-84bc-0346072c4156', 'device': 'bridge', 'type': 'interface'}, {'device': 'memballoon', 'specParams': {'model': 'virtio'}, 'type': 'balloon', 'deviceId': '09f59ef5-b17f-49ea-99e6-8ee7bcca64a1'}], 'smp': '2', 'vmType': 'kvm', 'timeOffset': '0', 'memSize': 1024, 'spiceSslCipherSuite': 'DEFAULT', 'cpuType': 'Conroe', 'spiceSecureChannels': 'smain,sinputs,scursor,splayback,srecord,sdisplay', 'smpCoresPerSocket': '2', 'vmName': 'bsdlinux04vm', 'display': 'qxl', 'transparentHugePages': 'true', 'nice': '0'},) {} flowID [8a5456c] Thread-1539::INFO::2012-10-30 09:56:09,203::API::601::vds::(_getNetworkIp) network None: using 0 Thread-1539::INFO::2012-10-30 09:56:09,204::API::228::vds::(create) vmContainerLock acquired by vm 4abdba0d-aa1f-48f1-8160-3cde63165057 Thread-1540::DEBUG::2012-10-30 09:56:09,207::vm::564::vm.Vm::(_startUnderlyingVm) vmId=`4abdba0d-aa1f-48f1-8160-3cde63165057`::Start Thread-1539::DEBUG::2012-10-30 09:56:09,207::API::244::vds::(create) Total desktops after creation of 4abdba0d-aa1f-48f1-8160-3cde63165057 is 1 Thread-1539::DEBUG::2012-10-30 09:56:09,208::BindingXMLRPC::865::vds::(wrapper) return vmCreate with {'status': {'message': 'Done', 'code': 0}, 'vmList': {'status': 'WaitForLaunch', 'acpiEnable': 'true', 'emulatedMachine': 'pc-0.14', 'vmId': '4abdba0d-aa1f-48f1-8160-3cde63165057', 'pid': '0', 'timeOffset': '0', 'displayPort': '-1', 'displaySecurePort': '-1', 'spiceSslCipherSuite': 'DEFAULT', 'cpuType': 'Conroe', 'custom': {'viodiskcache': 'writeback'}, 'clientIp': '', 'nicModel': 'rtl8139,pv', 'keyboardLayout': 'en-us', 'kvmEnable': 'true', 'pitReinjection': 'false', 'transparentHugePages': 'true', 'devices': [{'device': 'qxl', 'specParams': {'vram': '65536'}, 'type': 'video', 'deviceId': '25ada4cb-1108-491b-8d2c-c05cb353cc99'}, {'index': '2', 'iface': 'ide', 'bootOrder': '1', 'specParams': {'path': 'Fedora-17-x86_64-DVD.iso'}, 'readonly': 'true', 'deviceId': '1b62fc2d-88e5-42e0-9666-3de861a71c44', 'device': 'cdrom', 'path': '/rhev/data-center/640fa36c-1da8-11e2-86f7-1078d2e9dece/65f95655-5bbe-47e4-8d3a-6e2ffc5c7761/images/11111111-1111-1111-1111-111111111111/Fedora-17-x86_64-DVD.iso',
'type': 'disk'}, {'index': 0, 'iface': 'virtio', 'format': 'raw', 'type': 'disk', 'volumeID': '12413fe4-a694-439b-95d8-40d5a576dada', 'imageID': '025d5960-23db-4e07-98c8-4c9682155eb1', 'specParams': {}, 'readonly': 'false', 'domainID': 'e552b5fd-30fb-4e18-8bc4-26517f11a283', 'deviceId': '025d5960-23db-4e07-98c8-4c9682155eb1', 'poolID': '640fa36c-1da8-11e2-86f7-1078d2e9dece', 'device': 'disk', 'shared': 'false', 'propagateErrors': 'off', 'optional': 'false'}, {'nicModel': 'pv', 'macAddr': '00:1a:4a:70:83:00', 'network': 'ovirtmgmt', 'specParams': {}, 'deviceId': '80841d17-f758-46c8-84bc-0346072c4156', 'device': 'bridge', 'type': 'interface'}, {'device': 'memballoon', 'specParams': {'model': 'virtio'}, 'type': 'balloon', 'deviceId': '09f59ef5-b17f-49ea-99e6-8ee7bcca64a1'}], 'smp': '2', 'vmType': 'kvm', 'memSize': 1024, 'displayIp': '0', 'spiceSecureChannels': 'smain,sinputs,scursor,splayback,srecord,sdisplay', 'smpCoresPerSocket': '2', 'vmName': 'bsdlinux04vm', 'display': 'qxl', 'nice': '0'}} Thread-1540::DEBUG::2012-10-30 09:56:09,208::vm::568::vm.Vm::(_startUnderlyingVm) vmId=`4abdba0d-aa1f-48f1-8160-3cde63165057`::_ongoingCreations acquired Thread-1540::INFO::2012-10-30 09:56:09,210::libvirtvm::1285::vm.Vm::(_run) vmId=`4abdba0d-aa1f-48f1-8160-3cde63165057`::VM wrapper has started Thread-1540::DEBUG::2012-10-30 09:56:09,211::task::588::TaskManager.Task::(_updateState) Task=`f91ddc64-360b-4f33-bb53-9c6436a6a6d4`::moving from state init -> state preparing Thread-1540::INFO::2012-10-30 09:56:09,211::logUtils::37::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='e552b5fd-30fb-4e18-8bc4-26517f11a283', spUUID='640fa36c-1da8-11e2-86f7-1078d2e9dece', imgUUID='025d5960-23db-4e07-98c8-4c9682155eb1', volUUID='12413fe4-a694-439b-95d8-40d5a576dada', options=None) Thread-1540::DEBUG::2012-10-30 09:56:09,212::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283`ReqID=`a4d63aa4-f9af-48c3-b57f-68149d3ea523`::Request
was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource' Thread-1540::DEBUG::2012-10-30 09:56:09,212::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283' for lock type 'shared' Thread-1540::DEBUG::2012-10-30 09:56:09,212::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283' is free. Now locking as 'shared' (1 active user) Thread-1540::DEBUG::2012-10-30 09:56:09,213::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283`ReqID=`a4d63aa4-f9af-48c3-b57f-68149d3ea523`::Granted
request Thread-1540::DEBUG::2012-10-30 09:56:09,213::task::817::TaskManager.Task::(resourceAcquired) Task=`f91ddc64-360b-4f33-bb53-9c6436a6a6d4`::_resourcesAcquired: Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283 (shared) Thread-1540::DEBUG::2012-10-30 09:56:09,213::task::978::TaskManager.Task::(_decref) Task=`f91ddc64-360b-4f33-bb53-9c6436a6a6d4`::ref 1 aborting False Thread-1540::DEBUG::2012-10-30 09:56:09,216::fileVolume::535::Storage.Volume::(validateVolumePath) validate path for 12413fe4-a694-439b-95d8-40d5a576dada Thread-1540::DEBUG::2012-10-30 09:56:09,220::fileVolume::535::Storage.Volume::(validateVolumePath) validate path for 12413fe4-a694-439b-95d8-40d5a576dada Thread-1540::INFO::2012-10-30 09:56:09,221::logUtils::39::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '0', 'apparentsize': '8589934592'} Thread-1540::DEBUG::2012-10-30 09:56:09,221::task::1172::TaskManager.Task::(prepare) Task=`f91ddc64-360b-4f33-bb53-9c6436a6a6d4`::finished: {'truesize': '0', 'apparentsize': '8589934592'} Thread-1540::DEBUG::2012-10-30 09:56:09,222::task::588::TaskManager.Task::(_updateState) Task=`f91ddc64-360b-4f33-bb53-9c6436a6a6d4`::moving from state preparing -> state finished Thread-1540::DEBUG::2012-10-30 09:56:09,222::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283': < ResourceRef 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283', isValid: 'True' obj: 'None'>} Thread-1540::DEBUG::2012-10-30 09:56:09,222::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-1540::DEBUG::2012-10-30 09:56:09,222::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283' Thread-1540::DEBUG::2012-10-30 09:56:09,223::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283' (0 active users) Thread-1540::DEBUG::2012-10-30 09:56:09,223::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283' is free, finding out if anyone is waiting for it. Thread-1540::DEBUG::2012-10-30 09:56:09,223::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283', Clearing records. Thread-1540::DEBUG::2012-10-30 09:56:09,223::task::978::TaskManager.Task::(_decref) Task=`f91ddc64-360b-4f33-bb53-9c6436a6a6d4`::ref 0 aborting False Thread-1540::INFO::2012-10-30 09:56:09,224::clientIF::274::vds::(prepareVolumePath) prepared volume path: /rhev/data-center/640fa36c-1da8-11e2-86f7-1078d2e9dece/65f95655-5bbe-47e4-8d3a-6e2ffc5c7761/images/11111111-1111-1111-1111-111111111111/Fedora-17-x86_64-DVD.iso
Thread-1540::DEBUG::2012-10-30 09:56:09,224::task::588::TaskManager.Task::(_updateState) Task=`c1701ef5-96d8-4036-a5cb-7a285152d84f`::moving from state init -> state preparing Thread-1540::INFO::2012-10-30 09:56:09,224::logUtils::37::dispatcher::(wrapper) Run and protect: prepareImage(sdUUID='e552b5fd-30fb-4e18-8bc4-26517f11a283', spUUID='640fa36c-1da8-11e2-86f7-1078d2e9dece', imgUUID='025d5960-23db-4e07-98c8-4c9682155eb1', volUUID='12413fe4-a694-439b-95d8-40d5a576dada') Thread-1540::DEBUG::2012-10-30 09:56:09,225::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283`ReqID=`1fd9533e-6b8a-458d-a4d2-001f0cc93ac2`::Request
was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource' Thread-1540::DEBUG::2012-10-30 09:56:09,225::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283' for lock type 'shared' Thread-1540::DEBUG::2012-10-30 09:56:09,225::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283' is free. Now locking as 'shared' (1 active user) Thread-1540::DEBUG::2012-10-30 09:56:09,225::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283`ReqID=`1fd9533e-6b8a-458d-a4d2-001f0cc93ac2`::Granted
request Thread-1540::DEBUG::2012-10-30 09:56:09,226::task::817::TaskManager.Task::(resourceAcquired) Task=`c1701ef5-96d8-4036-a5cb-7a285152d84f`::_resourcesAcquired: Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283 (shared) Thread-1540::DEBUG::2012-10-30 09:56:09,226::task::978::TaskManager.Task::(_decref) Task=`c1701ef5-96d8-4036-a5cb-7a285152d84f`::ref 1 aborting False Thread-1540::DEBUG::2012-10-30 09:56:09,227::fileVolume::535::Storage.Volume::(validateVolumePath) validate path for 12413fe4-a694-439b-95d8-40d5a576dada Thread-1540::INFO::2012-10-30 09:56:09,234::image::357::Storage.Image::(getChain) sdUUID=e552b5fd-30fb-4e18-8bc4-26517f11a283 imgUUID=025d5960-23db-4e07-98c8-4c9682155eb1 chain=[<storage.fileVolume.FileVolume instance at 0x7f82442cb0e0>] Thread-1540::INFO::2012-10-30 09:56:09,237::logUtils::39::dispatcher::(wrapper) Run and protect: prepareImage, Return response: {'path': '/rhev/data-center/640fa36c-1da8-11e2-86f7-1078d2e9dece/e552b5fd-30fb-4e18-8bc4-26517f11a283/images/025d5960-23db-4e07-98c8-4c9682155eb1/12413fe4-a694-439b-95d8-40d5a576dada',
'chain': [{'path': '/rhev/data-center/640fa36c-1da8-11e2-86f7-1078d2e9dece/e552b5fd-30fb-4e18-8bc4-26517f11a283/images/025d5960-23db-4e07-98c8-4c9682155eb1/12413fe4-a694-439b-95d8-40d5a576dada',
'domainID': 'e552b5fd-30fb-4e18-8bc4-26517f11a283', 'volumeID': '12413fe4-a694-439b-95d8-40d5a576dada', 'imageID': '025d5960-23db-4e07-98c8-4c9682155eb1'}]} Thread-1540::DEBUG::2012-10-30 09:56:09,237::task::1172::TaskManager.Task::(prepare) Task=`c1701ef5-96d8-4036-a5cb-7a285152d84f`::finished: {'path': '/rhev/data-center/640fa36c-1da8-11e2-86f7-1078d2e9dece/e552b5fd-30fb-4e18-8bc4-26517f11a283/images/025d5960-23db-4e07-98c8-4c9682155eb1/12413fe4-a694-439b-95d8-40d5a576dada',
'chain': [{'path': '/rhev/data-center/640fa36c-1da8-11e2-86f7-1078d2e9dece/e552b5fd-30fb-4e18-8bc4-26517f11a283/images/025d5960-23db-4e07-98c8-4c9682155eb1/12413fe4-a694-439b-95d8-40d5a576dada',
'domainID': 'e552b5fd-30fb-4e18-8bc4-26517f11a283', 'volumeID': '12413fe4-a694-439b-95d8-40d5a576dada', 'imageID': '025d5960-23db-4e07-98c8-4c9682155eb1'}]} Thread-1540::DEBUG::2012-10-30 09:56:09,237::task::588::TaskManager.Task::(_updateState) Task=`c1701ef5-96d8-4036-a5cb-7a285152d84f`::moving from state preparing -> state finished Thread-1540::DEBUG::2012-10-30 09:56:09,237::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283': < ResourceRef 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283', isValid: 'True' obj: 'None'>} Thread-1540::DEBUG::2012-10-30 09:56:09,237::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-1540::DEBUG::2012-10-30 09:56:09,238::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283' Thread-1540::DEBUG::2012-10-30 09:56:09,238::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283' (0 active users) Thread-1540::DEBUG::2012-10-30 09:56:09,238::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283' is free, finding out if anyone is waiting for it. Thread-1540::DEBUG::2012-10-30 09:56:09,238::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283', Clearing records. Thread-1540::DEBUG::2012-10-30 09:56:09,239::task::978::TaskManager.Task::(_decref) Task=`c1701ef5-96d8-4036-a5cb-7a285152d84f`::ref 0 aborting False Thread-1540::INFO::2012-10-30 09:56:09,239::clientIF::274::vds::(prepareVolumePath) prepared volume path: /rhev/data-center/640fa36c-1da8-11e2-86f7-1078d2e9dece/e552b5fd-30fb-4e18-8bc4-26517f11a283/images/025d5960-23db-4e07-98c8-4c9682155eb1/12413fe4-a694-439b-95d8-40d5a576dada
Thread-1540::DEBUG::2012-10-30 09:56:09,249::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/libexec/vdsm/hooks/before_vm_start/50_hugepages' (cwd None) Thread-1540::DEBUG::2012-10-30 09:56:09,375::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0 Thread-1540::INFO::2012-10-30 09:56:09,376::hooks::72::root::(_runHooksDir) Thread-1540::DEBUG::2012-10-30 09:56:09,376::libvirtvm::1338::vm.Vm::(_run) vmId=`4abdba0d-aa1f-48f1-8160-3cde63165057`::<?xml version="1.0" encoding="utf-8"?> <domain type="kvm"> <name>bsdlinux04vm</name> <uuid>4abdba0d-aa1f-48f1-8160-3cde63165057</uuid> <memory>1048576</memory> <currentMemory>1048576</currentMemory> <vcpu>2</vcpu> <devices> <channel type="unix"> <target name="com.redhat.rhevm.vdsm" type="virtio"/> <source mode="bind" path="/var/lib/libvirt/qemu/channels/bsdlinux04vm.com.redhat.rhevm.vdsm"/>
</channel> <input bus="ps2" type="mouse"/> <channel type="spicevmc"> <target name="com.redhat.spice.0" type="virtio"/> </channel> <graphics autoport="yes" keymap="en-us" 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"/> </graphics> <console type="pty"> <target port="0" type="virtio"/> </console> <video> <model heads="1" type="qxl" vram="65536"/> </video> <interface type="bridge"> <mac address="00:1a:4a:70:83:00"/> <model type="virtio"/> <source bridge="ovirtmgmt"/> </interface> <memballoon model="virtio"/> <disk device="cdrom" snapshot="no" type="file"> <source file="/rhev/data-center/640fa36c-1da8-11e2-86f7-1078d2e9dece/65f95655-5bbe-47e4-8d3a-6e2ffc5c7761/images/11111111-1111-1111-1111-111111111111/Fedora-17-x86_64-DVD.iso"
startupPolicy="optional"/> <target bus="ide" dev="hdc"/> <readonly/> <serial></serial> <boot order="1"/> </disk> <disk device="disk" snapshot="no" type="file"> <source file="/rhev/data-center/640fa36c-1da8-11e2-86f7-1078d2e9dece/e552b5fd-30fb-4e18-8bc4-26517f11a283/images/025d5960-23db-4e07-98c8-4c9682155eb1/12413fe4-a694-439b-95d8-40d5a576dada"/>
<target bus="virtio" dev="vda"/> <serial>025d5960-23db-4e07-98c8-4c9682155eb1</serial> <driver cache="writeback" error_policy="stop" io="threads" name="qemu" type="raw"/> </disk> </devices> <os> <type arch="x86_64" machine="pc-0.14">hvm</type> <smbios mode="sysinfo"/> </os> <sysinfo type="smbios"> <system> <entry name="manufacturer">Red Hat</entry> <entry name="product">RHEV Hypervisor</entry> <entry name="version">17-1</entry> <entry name="serial">4C4C4544-0059-4810-8034-B7C04F463253_d4:ae:52:a3:1c:1e</entry>
<entry name="uuid">4abdba0d-aa1f-48f1-8160-3cde63165057</entry> </system> </sysinfo> <clock adjustment="0" offset="variable"> <timer name="rtc" tickpolicy="catchup"/> </clock> <features> <acpi/> </features> <cpu match="exact"> <model>Conroe</model> <topology cores="2" sockets="1" threads="1"/> </cpu> </domain>
libvirtEventLoop::DEBUG::2012-10-30 09:56:10,075::libvirtvm::2409::vm.Vm::(_onLibvirtLifecycleEvent) vmId=`4abdba0d-aa1f-48f1-8160-3cde63165057`::event Started detail 0 opaque None Thread-1540::DEBUG::2012-10-30 09:56:10,188::utils::329::vm.Vm::(start) vmId=`4abdba0d-aa1f-48f1-8160-3cde63165057`::Start statistics collection Thread-1542::DEBUG::2012-10-30 09:56:10,188::utils::358::vm.Vm::(run) vmId=`4abdba0d-aa1f-48f1-8160-3cde63165057`::Stats thread started Thread-1542::DEBUG::2012-10-30 09:56:10,189::task::588::TaskManager.Task::( _updateState) Task=`6a004d5d-63a9-4ffb-a887-8f7d5c6179c7`::moving from state init -> state preparing Thread-1542::INFO::2012-10-30 09:56:10,190::logUtils::37::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='e552b5fd-30fb-4e18-8bc4-26517f11a283', spUUID='640fa36c-1da8-11e2-86f7-1078d2e9dece', imgUUID='025d5960-23db-4e07-98c8-4c9682155eb1', volUUID='12413fe4-a694-439b-95d8-40d5a576dada', options=None) Thread-1542::DEBUG::2012-10-30 09:56:10,191::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283`ReqID=`057d2200-a704-4de4-a45b-2771d72f30bb`::Request
was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource' Thread-1542::DEBUG::2012-10-30 09:56:10,191::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283' for lock type 'shared' Thread-1540::DEBUG::2012-10-30 09:56:10,192::vmChannels::144::vds::(register) Add fileno 18 to listener's channels. Thread-1542::DEBUG::2012-10-30 09:56:10,192::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283' is free. Now locking as 'shared' (1 active user) Thread-1542::DEBUG::2012-10-30 09:56:10,193::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283`ReqID=`057d2200-a704-4de4-a45b-2771d72f30bb`::Granted
request Thread-1542::DEBUG::2012-10-30 09:56:10,193::task::817::TaskManager.Task::(resourceAcquired) Task=`6a004d5d-63a9-4ffb-a887-8f7d5c6179c7`::_resourcesAcquired: Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283 (shared) Thread-1542::DEBUG::2012-10-30 09:56:10,193::task::978::TaskManager.Task::(_decref) Task=`6a004d5d-63a9-4ffb-a887-8f7d5c6179c7`::ref 1 aborting False Thread-1542::DEBUG::2012-10-30 09:56:10,195::fileVolume::535::Storage.Volume::(validateVolumePath) validate path for 12413fe4-a694-439b-95d8-40d5a576dada Thread-1540::WARNING::2012-10-30 09:56:10,196::libvirtvm::1547::vm.Vm::(_readPauseCode) vmId=`4abdba0d-aa1f-48f1-8160-3cde63165057`::_readPauseCode unsupported by libvirt vm Thread-1542::DEBUG::2012-10-30 09:56:10,199::fileVolume::535::Storage.Volume::(validateVolumePath) validate path for 12413fe4-a694-439b-95d8-40d5a576dada Thread-1542::INFO::2012-10-30 09:56:10,200::logUtils::39::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '0', 'apparentsize': '8589934592'} Thread-1542::DEBUG::2012-10-30 09:56:10,200::task::1172::TaskManager.Task::(prepare) Task=`6a004d5d-63a9-4ffb-a887-8f7d5c6179c7`::finished: {'truesize': '0', 'apparentsize': '8589934592'} Thread-1542::DEBUG::2012-10-30 09:56:10,201::task::588::TaskManager.Task::(_updateState) Task=`6a004d5d-63a9-4ffb-a887-8f7d5c6179c7`::moving from state preparing -> state finished Thread-1542::DEBUG::2012-10-30 09:56:10,201::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283': < ResourceRef 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283', isValid: 'True' obj: 'None'>} Thread-1542::DEBUG::2012-10-30 09:56:10,201::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-1542::DEBUG::2012-10-30 09:56:10,201::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283' Thread-1542::DEBUG::2012-10-30 09:56:10,202::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283' (0 active users) Thread-1542::DEBUG::2012-10-30 09:56:10,202::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283' is free, finding out if anyone is waiting for it. Thread-1542::DEBUG::2012-10-30 09:56:10,203::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.e552b5fd-30fb-4e18-8bc4-26517f11a283', Clearing records. Thread-1542::DEBUG::2012-10-30 09:56:10,203::task::978::TaskManager.Task::(_decref) Task=`6a004d5d-63a9-4ffb-a887-8f7d5c6179c7`::ref 0 aborting False Thread-1540::DEBUG::2012-10-30 09:56:10,206::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /usr/sbin/service ksmtuned retune' (cwd None) Thread-1540::DEBUG::2012-10-30 09:56:10,241::__init__::1249::Storage.Misc.excCmd::(_log) FAILED: <err> = "Redirecting to /bin/systemctl retune ksmtuned.service\nUnknown operation 'retune'.\n"; <rc> = 1 Thread-1540::DEBUG::2012-10-30 09:56:10,242::vm::580::vm.Vm::(_startUnde rlyingVm) vmId=`4abdba0d-aa1f-48f1-8160-3cde63165057`::_ongoingCreations released VM Channels Listener::DEBUG::2012-10-30 09:56:10,376::vmChannels::71::vds::(_do_add_channels) fileno 18 was added to unconnected channels. VM Channels Listener::DEBUG::2012-10-30 09:56:10,376::vmChannels::103::vds::(_handle_unconnected) Trying to connect fileno 18. VM Channels Listener::DEBUG::2012-10-30 09:56:10,376::guestIF::81::vm.Vm::(_connect) vmId=`4abdba0d-aa1f-48f1-8160-3cde63165057`::Attempting connection to /var/lib/libvirt/qemu/channels/bsdlinux04vm.com.redhat.rhevm.vdsm VM Channels Listener::DEBUG::2012-10-30 09:56:10,377::guestIF::83::vm.Vm::(_connect) vmId=`4abdba0d-aa1f-48f1-8160-3cde63165057`::Connected to /var/lib/libvirt/qemu/channels/bsdlinux04vm.com.redhat.rhevm.vdsm VM Channels Listener::DEBUG::2012-10-30 09:56:10,377::vmChannels::106::vds::(_handle_unconnected) Connect fileno 18 was succeed. Thread-1543::DEBUG::2012-10-30 09:56:14,759::BindingXMLRPC::156::vds::(wrapper) [192.168.1.10] Thread-1543::DEBUG::2012-10-30 09:56:14,760::task::588::TaskManager.Task::(_updateState) Task=`3379e8b3-bf70-49d0-b643-0bb17de93846`::moving from state init -> state preparing Thread-1543::INFO::2012-10-30 09:56:14,760::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='640fa36c-1da8-11e2-86f7-1078d2e9dece', options=None) Thread-1543::INFO::2012-10-30 09:56:14,761::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 1}} Thread-1543::DEBUG::2012-10-30 09:56:14,761::task::1172::TaskManager.Task::(prepare) Task=`3379e8b3-bf70-49d0-b643-0bb17de93846`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 1}} Thread-1543::DEBUG::2012-10-30 09:56:14,761::task::588::TaskManager.Task::(_updateState) Task=`3379e8b3-bf70-49d0-b643-0bb17de93846`::moving from state preparing -> state finished Thread-1543::DEBUG::2012-10-30 09:56:14,761::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-1543::DEBUG::2012-10-30 09:56:14,762::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-1543::DEBUG::2012-10-30 09:56:14,762::task::978::TaskManager.Task::(_decref) Task=`3379e8b3-bf70-49d0-b643-0bb17de93846`::ref 0 aborting False Thread-1544::DEBUG::2012-10-30 09:56:14,781::BindingXMLRPC::156::vds::(wrapper) [192.168.1.10] Thread-1544::DEBUG::2012-10-30 09:56:14,782::task::588::TaskManager.Task::(_updateState) Task=`f7a0fd20-fddb-48f7-832e-ed230b49d4f0`::moving from state init -> state preparing Thread-1544::INFO::2012-10-30 09:56:14,782::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='640fa36c-1da8-11e2-86f7-1078d2e9dece', options=None) Thread-1544::DEBUG::2012-10-30 09:56:14,782::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece`ReqID=`7e21374b-d582-451f-b37a-ee1ea2f206f1`::Request
was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource' Thread-1544::DEBUG::2012-10-30 09:56:14,783::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece' for lock type 'shared' Thread-1544::DEBUG::2012-10-30 09:56:14,783::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece' is free. Now locking as 'shared' (1 active user) Thread-1544::DEBUG::2012-10-30 09:56:14,783::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece`ReqID=`7e21374b-d582-451f-b37a-ee1ea2f206f1`::Granted
request Thread-1544::DEBUG::2012-10-30 09:56:14,784::task::817::TaskManager.Task::(resourceAcquired) Task=`f7a0fd20-fddb-48f7-832e-ed230b49d4f0`::_resourcesAcquired: Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece (shared) Thread-1544::DEBUG::2012-10-30 09:56:14,784::task::978::TaskManager.Task::(_decref) Task=`f7a0fd20-fddb-48f7-832e-ed230b49d4f0`::ref 1 aborting False Thread-1544::INFO::2012-10-30 09:56:14,793::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': 'e552b5fd-30fb-4e18-8bc4-26517f11a283', 'name': 'Default', 'version': '0', 'domains': '65f95655-5bbe-47e4-8d3a-6e2ffc5c7761:Active,e552b5fd-30fb-4e18-8bc4-26517f11a283:Active',
'pool_status': 'connected', 'isoprefix': '/rhev/data-center/640fa36c-1da8-11e2-86f7-1078d2e9dece/65f95655-5bbe-47e4-8d3a-6e2ffc5c7761/images/11111111-1111-1111-1111-111111111111',
'type': 'SHAREDFS', 'master_ver': 1, 'lver': 1}, 'dominfo': {'65f95655-5bbe-47e4-8d3a-6e2ffc5c7761': {'status': 'Active', 'diskfree': '382827757568', 'alerts': [], 'disktotal': '424540110848'}, 'e552b5fd-30fb-4e18-8bc4-26517f11a283': {'status': 'Active', 'diskfree': '2099627163648', 'alerts': [], 'disktotal': '2212208836608'}}} Thread-1544::DEBUG::2012-10-30 09:56:14,793::task::1172::TaskManager.Task::(prepare) Task=`f7a0fd20-fddb-48f7-832e-ed230b49d4f0`::finished: {'info': {'spm_id': 1, 'master_uuid': 'e552b5fd-30fb-4e18-8bc4-26517f11a283', 'name': 'Default', 'version': '0', 'domains': '65f95655-5bbe-47e4-8d3a-6e2ffc5c7761:Active,e552b5fd-30fb-4e18-8bc4-26517f11a283:Active',
'pool_status': 'connected', 'isoprefix': '/rhev/data-center/640fa36c-1da8-11e2-86f7-1078d2e9dece/65f95655-5bbe-47e4-8d3a-6e2ffc5c7761/images/11111111-1111-1111-1111-111111111111',
'type': 'SHAREDFS', 'master_ver': 1, 'lver': 1}, 'dominfo': {'65f95655-5bbe-47e4-8d3a-6e2ffc5c7761': {'status': 'Active', 'diskfree': '382827757568', 'alerts': [], 'disktotal': '424540110848'}, 'e552b5fd-30fb-4e18-8bc4-26517f11a283': {'status': 'Active', 'diskfree': '2099627163648', 'alerts': [], 'disktotal': '2212208836608'}}} Thread-1544::DEBUG::2012-10-30 09:56:14,794::task::588::TaskManager.Task::(_updateState) Task=`f7a0fd20-fddb-48f7-832e-ed230b49d4f0`::moving from state preparing -> state finished Thread-1544::DEBUG::2012-10-30 09:56:14,794::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece': < ResourceRef 'Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece', isValid: 'True' obj: 'None'>} Thread-1544::DEBUG::2012-10-30 09:56:14,794::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-1544::DEBUG::2012-10-30 09:56:14,794::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece' Thread-1544::DEBUG::2012-10-30 09:56:14,795::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece' (0 active users) Thread-1544::DEBUG::2012-10-30 09:56:14,795::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece' is free, finding out if anyone is waiting for it. Thread-1544::DEBUG::2012-10-30 09:56:14,795::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece', Clearing records. Thread-1544::DEBUG::2012-10-30 09:56:14,795::task::978::TaskManager.Task::(_decref) Task=`f7a0fd20-fddb-48f7-832e-ed230b49d4f0`::ref 0 aborting False Thread-1545::DEBUG::2012-10-30 09:56:24,820::BindingXMLRPC::156::vds::(wrapper) [192.168.1.10] Thread-1545::DEBUG::2012-10-30 09:56:24,820::task::588::TaskManager.Task::(_updateState) Task=`911438a8-fbf0-456f-b979-9e361bda85f2`::moving from state init -> state preparing Thread-1545::INFO::2012-10-30 09:56:24,821::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='640fa36c-1da8-11e2-86f7-1078d2e9dece', options=None) Thread-1545::INFO::2012-10-30 09:56:24,821::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 1}} Thread-1545::DEBUG::2012-10-30 09:56:24,821::task::1172::TaskManager.Task::(prepare) Task=`911438a8-fbf0-456f-b979-9e361bda85f2`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 1}} Thread-1545::DEBUG::2012-10-30 09:56:24,822::task::588::TaskManager.Task::(_updateState) Task=`911438a8-fbf0-456f-b979-9e361bda85f2`::moving from state preparing -> state finished Thread-1545::DEBUG::2012-10-30 09:56:24,822::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-1545::DEBUG::2012-10-30 09:56:24,822::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-1545::DEBUG::2012-10-30 09:56:24,822::task::978::TaskManager.Task::(_decref) Task=`911438a8-fbf0-456f-b979-9e361bda85f2`::ref 0 aborting False Thread-1546::DEBUG::2012-10-30 09:56:24,840::BindingXMLRPC::156::vds::(wrapper) [192.168.1.10] Thread-1546::DEBUG::2012-10-30 09:56:24,841::task::588::TaskManager.Task::(_updateState) Task=`fbf6f12b-58f8-45bf-b34f-5fa3ae93123c`::moving from state init -> state preparing Thread-1546::INFO::2012-10-30 09:56:24,841::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='640fa36c-1da8-11e2-86f7-1078d2e9dece', options=None) Thread-1546::DEBUG::2012-10-30 09:56:24,841::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece`ReqID=`c8c2813e-c44c-44f2-b1dd-0f797ecadce3`::Request
was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource' Thread-1546::DEBUG::2012-10-30 09:56:24,842::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece' for lock type 'shared' Thread-1546::DEBUG::2012-10-30 09:56:24,842::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece' is free. Now locking as 'shared' (1 active user) Thread-1546::DEBUG::2012-10-30 09:56:24,842::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece`ReqID=`c8c2813e-c44c-44f2-b1dd-0f797ecadce3`::Granted
request Thread-1546::DEBUG::2012-10-30 09:56:24,843::task::817::TaskManager.Task::(resourceAcquired) Task=`fbf6f12b-58f8-45bf-b34f-5fa3ae93123c`::_resourcesAcquired: Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece (shared) Thread-1546::DEBUG::2012-10-30 09:56:24,843::task::978::TaskManager.Task::(_decref) Task=`fbf6f12b-58f8-45bf-b34f-5fa3ae93123c`::ref 1 aborting False Thread-1546::INFO::2012-10-30 09:56:24,852::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': 'e552b5fd-30fb-4e18-8bc4-26517f11a283', 'name': 'Default', 'version': '0', 'domains': '65f95655-5bbe-47e4-8d3a-6e2ffc5c7761:Active,e552b5fd-30fb-4e18-8bc4-26517f11a283:Active',
'pool_status': 'connected', 'isoprefix': '/rhev/data-center/640fa36c-1da8-11e2-86f7-1078d2e9dece/65f95655-5bbe-47e4-8d3a-6e2ffc5c7761/images/11111111-1111-1111-1111-111111111111',
'type': 'SHAREDFS', 'master_ver': 1, 'lver': 1}, 'dominfo': {'65f95655-5bbe-47e4-8d3a-6e2ffc5c7761': {'status': 'Active', 'diskfree': '382827757568', 'alerts': [], 'disktotal': '424540110848'}, 'e552b5fd-30fb-4e18-8bc4-26517f11a283': {'status': 'Active', 'diskfree': '2099627163648', 'alerts': [], 'disktotal': '2212208836608'}}} Thread-1546::DEBUG::2012-10-30 09:56:24,853::task::1172::TaskManager.Task::(prepare) Task=`fbf6f12b-58f8-45bf-b34f-5fa3ae93123c`::finished: {'info': {'spm_id': 1, 'master_uuid': 'e552b5fd-30fb-4e18-8bc4-26517f11a283', 'name': 'Default', 'version': '0', 'domains': '65f95655-5bbe-47e4-8d3a-6e2ffc5c7761:Active,e552b5fd-30fb-4e18-8bc4-26517f11a283:Active',
'pool_status': 'connected', 'isoprefix': '/rhev/data-center/640fa36c-1da8-11e2-86f7-1078d2e9dece/65f95655-5bbe-47e4-8d3a-6e2ffc5c7761/images/11111111-1111-1111-1111-111111111111',
'type': 'SHAREDFS', 'master_ver': 1, 'lver': 1}, 'dominfo': {'65f95655-5bbe-47e4-8d3a-6e2ffc5c7761': {'status': 'Active', 'diskfree': '382827757568', 'alerts': [], 'disktotal': '424540110848'}, 'e552b5fd-30fb-4e18-8bc4-26517f11a283': {'status': 'Active', 'diskfree': '2099627163648', 'alerts': [], 'disktotal': '2212208836608'}}} Thread-1546::DEBUG::2012-10-30 09:56:24,853::task::588::TaskManager.Task::(_updateState) Task=`fbf6f12b-58f8-45bf-b34f-5fa3ae93123c`::moving from state preparing -> state finished Thread-1546::DEBUG::2012-10-30 09:56:24,853::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece': < ResourceRef 'Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece', isValid: 'True' obj: 'None'>} Thread-1546::DEBUG::2012-10-30 09:56:24,853::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-1546::DEBUG::2012-10-30 09:56:24,854::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece' Thread-1546::DEBUG::2012-10-30 09:56:24,854::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece' (0 active users) Thread-1546::DEBUG::2012-10-30 09:56:24,854::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece' is free, finding out if anyone is waiting for it. Thread-1546::DEBUG::2012-10-30 09:56:24,854::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.640fa36c-1da8-11e2-86f7-1078d2e9dece', Clearing records. Thread-1546::DEBUG::2012-10-30 09:56:24,855::task::978::TaskManager.Task::(_decref) Task=`fbf6f12b-58f8-45bf-b34f-5fa3ae93123c`::ref 0 aborting False
Regards Daniel Rowe _______________________________________________ Users mailing list Users@ovirt.org http://lists.ovirt.org/mailman/listinfo/users
_______________________________________________ Users mailing list Users@ovirt.org http://lists.ovirt.org/mailman/listinfo/users
participants (3)
-
Daniel Rowe
-
Itamar Heim
-
Roy Golan