9:05 p.m.
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
1:40 a.m.
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(a)ovirt.org
http://lists.ovirt.org/mailman/listinfo/users
2:47 a.m.
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(a)ovirt.org
> http://lists.ovirt.org/mailman/listinfo/users
_______________________________________________
Users mailing list
Users(a)ovirt.org
http://lists.ovirt.org/mailman/listinfo/users
4408
days inactive
4408
days old
2 comments
3 participants
participants (3)
-
Daniel Rowe -
Itamar Heim -
Roy Golan