Attachment 896415 Details for Bug 1098539 – VDSM log excerpt

VDSM log excerpt

vdsm_snippet.log (text/x-log), 16.97 KB, created by Francesco Romani on 2014-05-16 14:01:49 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Francesco Romani

Created: 2014-05-16 14:01:49 UTC

Size: 16.97 KB

patch

obsolete

>Thread-116::INFO::2014-05-16 15:30:51,081::clientIF::372::vds::(createVm) vmContainerLock acquired by vm 9e33ca94-1cf7-4791-b063-c4709482f691
>Thread-116::DEBUG::2014-05-16 15:30:51,083::clientIF::385::vds::(createVm) Total desktops after creation of 9e33ca94-1cf7-4791-b063-c4709482f691 is 1
>Thread-141::DEBUG::2014-05-16 15:30:51,083::vm::1925::vm.Vm::(_startUnderlyingVm) vmId=`9e33ca94-1cf7-4791-b063-c4709482f691`::Start
>Thread-116::DEBUG::2014-05-16 15:30:51,084::BindingXMLRPC::1063::vds::(wrapper) return vmCreate with {'status': {'message': 'Done', 'code': 0}, 'vmList': {'status': 'WaitForLaunch', 'acpiEnable': 'true', 'emulatedMachine': 'pc-1.0', 'vmId': '9e33ca94-1cf7-4791-b063-c4709482f691', 'pid': '0', 'memGuaranteedSize': 1024, 'timeOffset': '0', 'keyboardLayout': 'en-us', 'displayPort': '-1', 'displaySecurePort': '-1', 'spiceSslCipherSuite': 'DEFAULT', 'cpuType': 'Westmere', 'smp': '1', 'clientIp': '', 'transparentHugePages': 'true', 'nicModel': 'rtl8139,pv', 'smartcardEnable': 'false', 'kvmEnable': 'true', 'bootMenuEnable': 'false', 'numaTune': {'nodeset': '', 'mode': 'preferred'}, 'devices': [{'device': 'qxl', 'specParams': {'vram': '32768', 'heads': '1'}, 'type': 'video', 'deviceId': '80eee586-1bda-4f72-bd1d-3cb6ef6688d5'}, {'index': '2', 'iface': 'ide', 'bootOrder': '1', 'specParams': {'path': 'f19.iso'}, 'readonly': 'true', 'deviceId': '4f15a668-6426-48b9-92b7-dad3d79c6288', 'path': '/rhev/data-center/mnt/dellserver.home:_var_lib_exports_iso-20140516130700/cdd53e08-b51b-4ce9-b508-180e7c0be7d2/images/11111111-1111-1111-1111-111111111111/f19.iso', 'device': 'cdrom', 'shared': 'false', 'type': 'disk'}, {'index': 0, 'iface': 'virtio', 'format': 'raw', 'type': 'disk', 'volumeID': 'c79ca92e-abce-4fed-85f6-e7702f19f04a', 'imageID': 'fca201d2-7a8f-405e-953e-d7fe10456fde', 'specParams': {}, 'readonly': 'false', 'domainID': 'fbe886d2-c61a-4f97-818c-528ac5e0ca0d', 'deviceId': 'fca201d2-7a8f-405e-953e-d7fe10456fde', 'poolID': 'ffb30501-9c00-4632-934c-12bc06a291d1', 'device': 'disk', 'shared': 'false', 'propagateErrors': 'off', 'optional': 'false'}, {'nicModel': 'pv', 'macAddr': '00:1A:4A:B2:A2:50', 'linkActive': 'true', 'network': 'ovirtmgmt', 'filter': 'vdsm-no-mac-spoofing', 'specParams': {}, 'deviceId': 'c7c8a534-c5b1-4379-ae2c-931ea30cf864', 'device': 'bridge', 'type': 'interface'}, {'index': '0', 'specParams': {}, 'deviceId': '49f55015-ea2d-4661-97e0-a7662a27a5c4', 'device': 'scsi', 'model': 'virtio-scsi', 'type': 'controller'}], 'custom': {}, 'vmType': 'kvm', 'memSize': 1024, 'displayIp': '0', 'maxVCpus': '160', 'spiceSecureChannels': 'smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard', 'smpCoresPerSocket': '1', 'vmName': 'test', 'display': 'qxl', 'nice': '0'}}
>Thread-141::DEBUG::2014-05-16 15:30:51,084::vm::1929::vm.Vm::(_startUnderlyingVm) vmId=`9e33ca94-1cf7-4791-b063-c4709482f691`::_ongoingCreations acquired
>Thread-141::INFO::2014-05-16 15:30:51,085::vm::2802::vm.Vm::(_run) vmId=`9e33ca94-1cf7-4791-b063-c4709482f691`::VM wrapper has started
>Thread-141::DEBUG::2014-05-16 15:30:51,087::task::595::TaskManager.Task::(_updateState) Task=`6409b6ef-632d-4ac1-8686-62a37bb57f5b`::moving from state init -> state preparing
>Thread-141::INFO::2014-05-16 15:30:51,088::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='fbe886d2-c61a-4f97-818c-528ac5e0ca0d', spUUID='ffb30501-9c00-4632-934c-12bc06a291d1', imgUUID='fca201d2-7a8f-405e-953e-d7fe10456fde', volUUID='c79ca92e-abce-4fed-85f6-e7702f19f04a', options=None)
>Thread-141::INFO::2014-05-16 15:30:51,089::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '0', 'apparentsize': '10737418240'}
>Thread-141::DEBUG::2014-05-16 15:30:51,089::task::1188::TaskManager.Task::(prepare) Task=`6409b6ef-632d-4ac1-8686-62a37bb57f5b`::finished: {'truesize': '0', 'apparentsize': '10737418240'}
>Thread-141::DEBUG::2014-05-16 15:30:51,090::task::595::TaskManager.Task::(_updateState) Task=`6409b6ef-632d-4ac1-8686-62a37bb57f5b`::moving from state preparing -> state finished
>Thread-141::DEBUG::2014-05-16 15:30:51,090::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-141::DEBUG::2014-05-16 15:30:51,090::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-141::DEBUG::2014-05-16 15:30:51,090::task::993::TaskManager.Task::(_decref) Task=`6409b6ef-632d-4ac1-8686-62a37bb57f5b`::ref 0 aborting False
>Thread-141::INFO::2014-05-16 15:30:51,090::clientIF::313::vds::(prepareVolumePath) prepared volume path: /rhev/data-center/mnt/dellserver.home:_var_lib_exports_iso-20140516130700/cdd53e08-b51b-4ce9-b508-180e7c0be7d2/images/11111111-1111-1111-1111-111111111111/f19.iso
>Thread-141::DEBUG::2014-05-16 15:30:51,090::task::595::TaskManager.Task::(_updateState) Task=`eb9a173d-2a53-444e-84de-95508c427398`::moving from state init -> state preparing
>Thread-141::INFO::2014-05-16 15:30:51,091::logUtils::44::dispatcher::(wrapper) Run and protect: prepareImage(sdUUID='fbe886d2-c61a-4f97-818c-528ac5e0ca0d', spUUID='ffb30501-9c00-4632-934c-12bc06a291d1', imgUUID='fca201d2-7a8f-405e-953e-d7fe10456fde', leafUUID='c79ca92e-abce-4fed-85f6-e7702f19f04a')
>Thread-141::DEBUG::2014-05-16 15:30:51,091::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.fbe886d2-c61a-4f97-818c-528ac5e0ca0d`ReqID=`09cb9509-e7c2-4f47-be41-95759ede30a3`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3211' at 'prepareImage'
>Thread-141::DEBUG::2014-05-16 15:30:51,091::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.fbe886d2-c61a-4f97-818c-528ac5e0ca0d' for lock type 'shared'
>Thread-141::DEBUG::2014-05-16 15:30:51,091::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.fbe886d2-c61a-4f97-818c-528ac5e0ca0d' is free. Now locking as 'shared' (1 active user)
>Thread-141::DEBUG::2014-05-16 15:30:51,091::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.fbe886d2-c61a-4f97-818c-528ac5e0ca0d`ReqID=`09cb9509-e7c2-4f47-be41-95759ede30a3`::Granted request
>Thread-141::DEBUG::2014-05-16 15:30:51,091::task::827::TaskManager.Task::(resourceAcquired) Task=`eb9a173d-2a53-444e-84de-95508c427398`::_resourcesAcquired: Storage.fbe886d2-c61a-4f97-818c-528ac5e0ca0d (shared)
>Thread-141::DEBUG::2014-05-16 15:30:51,092::task::993::TaskManager.Task::(_decref) Task=`eb9a173d-2a53-444e-84de-95508c427398`::ref 1 aborting False
>Thread-141::DEBUG::2014-05-16 15:30:51,092::fileSD::508::Storage.StorageDomain::(activateVolumes) Fixing permissions on /rhev/data-center/mnt/dellserver.home:_home_images/fbe886d2-c61a-4f97-818c-528ac5e0ca0d/images/fca201d2-7a8f-405e-953e-d7fe10456fde/c79ca92e-abce-4fed-85f6-e7702f19f04a
>Thread-141::DEBUG::2014-05-16 15:30:51,092::fileUtils::142::Storage.fileUtils::(createdir) Creating directory: /var/run/vdsm/storage/fbe886d2-c61a-4f97-818c-528ac5e0ca0d
>Thread-141::WARNING::2014-05-16 15:30:51,092::fileUtils::149::Storage.fileUtils::(createdir) Dir /var/run/vdsm/storage/fbe886d2-c61a-4f97-818c-528ac5e0ca0d already exists
>Thread-141::DEBUG::2014-05-16 15:30:51,092::fileSD::483::Storage.StorageDomain::(createImageLinks) Creating symlink from /rhev/data-center/mnt/dellserver.home:_home_images/fbe886d2-c61a-4f97-818c-528ac5e0ca0d/images/fca201d2-7a8f-405e-953e-d7fe10456fde to /var/run/vdsm/storage/fbe886d2-c61a-4f97-818c-528ac5e0ca0d/fca201d2-7a8f-405e-953e-d7fe10456fde
>Thread-141::DEBUG::2014-05-16 15:30:51,093::fileSD::488::Storage.StorageDomain::(createImageLinks) img run dir already exists: /var/run/vdsm/storage/fbe886d2-c61a-4f97-818c-528ac5e0ca0d/fca201d2-7a8f-405e-953e-d7fe10456fde
>Thread-141::DEBUG::2014-05-16 15:30:51,093::fileVolume::536::Storage.Volume::(validateVolumePath) validate path for c79ca92e-abce-4fed-85f6-e7702f19f04a
>Thread-141::INFO::2014-05-16 15:30:51,093::logUtils::47::dispatcher::(wrapper) Run and protect: prepareImage, Return response: {'info': {'domainID': 'fbe886d2-c61a-4f97-818c-528ac5e0ca0d', 'volType': 'path', 'leaseOffset': 0, 'path': '/rhev/data-center/mnt/dellserver.home:_home_images/fbe886d2-c61a-4f97-818c-528ac5e0ca0d/images/fca201d2-7a8f-405e-953e-d7fe10456fde/c79ca92e-abce-4fed-85f6-e7702f19f04a', 'volumeID': 'c79ca92e-abce-4fed-85f6-e7702f19f04a', 'leasePath': '/rhev/data-center/mnt/dellserver.home:_home_images/fbe886d2-c61a-4f97-818c-528ac5e0ca0d/images/fca201d2-7a8f-405e-953e-d7fe10456fde/c79ca92e-abce-4fed-85f6-e7702f19f04a.lease', 'imageID': 'fca201d2-7a8f-405e-953e-d7fe10456fde'}, 'path': '/rhev/data-center/mnt/dellserver.home:_home_images/fbe886d2-c61a-4f97-818c-528ac5e0ca0d/images/fca201d2-7a8f-405e-953e-d7fe10456fde/c79ca92e-abce-4fed-85f6-e7702f19f04a', 'imgVolumesInfo': [{'domainID': 'fbe886d2-c61a-4f97-818c-528ac5e0ca0d', 'volType': 'path', 'leaseOffset': 0, 'path': '/rhev/data-center/mnt/dellserver.home:_home_images/fbe886d2-c61a-4f97-818c-528ac5e0ca0d/images/fca201d2-7a8f-405e-953e-d7fe10456fde/c79ca92e-abce-4fed-85f6-e7702f19f04a', 'volumeID': 'c79ca92e-abce-4fed-85f6-e7702f19f04a', 'leasePath': '/rhev/data-center/mnt/dellserver.home:_home_images/fbe886d2-c61a-4f97-818c-528ac5e0ca0d/images/fca201d2-7a8f-405e-953e-d7fe10456fde/c79ca92e-abce-4fed-85f6-e7702f19f04a.lease', 'imageID': 'fca201d2-7a8f-405e-953e-d7fe10456fde'}]}
>Thread-141::DEBUG::2014-05-16 15:30:51,093::task::1188::TaskManager.Task::(prepare) Task=`eb9a173d-2a53-444e-84de-95508c427398`::finished: {'info': {'domainID': 'fbe886d2-c61a-4f97-818c-528ac5e0ca0d', 'volType': 'path', 'leaseOffset': 0, 'path': '/rhev/data-center/mnt/dellserver.home:_home_images/fbe886d2-c61a-4f97-818c-528ac5e0ca0d/images/fca201d2-7a8f-405e-953e-d7fe10456fde/c79ca92e-abce-4fed-85f6-e7702f19f04a', 'volumeID': 'c79ca92e-abce-4fed-85f6-e7702f19f04a', 'leasePath': '/rhev/data-center/mnt/dellserver.home:_home_images/fbe886d2-c61a-4f97-818c-528ac5e0ca0d/images/fca201d2-7a8f-405e-953e-d7fe10456fde/c79ca92e-abce-4fed-85f6-e7702f19f04a.lease', 'imageID': 'fca201d2-7a8f-405e-953e-d7fe10456fde'}, 'path': '/rhev/data-center/mnt/dellserver.home:_home_images/fbe886d2-c61a-4f97-818c-528ac5e0ca0d/images/fca201d2-7a8f-405e-953e-d7fe10456fde/c79ca92e-abce-4fed-85f6-e7702f19f04a', 'imgVolumesInfo': [{'domainID': 'fbe886d2-c61a-4f97-818c-528ac5e0ca0d', 'volType': 'path', 'leaseOffset': 0, 'path': '/rhev/data-center/mnt/dellserver.home:_home_images/fbe886d2-c61a-4f97-818c-528ac5e0ca0d/images/fca201d2-7a8f-405e-953e-d7fe10456fde/c79ca92e-abce-4fed-85f6-e7702f19f04a', 'volumeID': 'c79ca92e-abce-4fed-85f6-e7702f19f04a', 'leasePath': '/rhev/data-center/mnt/dellserver.home:_home_images/fbe886d2-c61a-4f97-818c-528ac5e0ca0d/images/fca201d2-7a8f-405e-953e-d7fe10456fde/c79ca92e-abce-4fed-85f6-e7702f19f04a.lease', 'imageID': 'fca201d2-7a8f-405e-953e-d7fe10456fde'}]}
>Thread-141::DEBUG::2014-05-16 15:30:51,094::task::595::TaskManager.Task::(_updateState) Task=`eb9a173d-2a53-444e-84de-95508c427398`::moving from state preparing -> state finished
>Thread-141::DEBUG::2014-05-16 15:30:51,094::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.fbe886d2-c61a-4f97-818c-528ac5e0ca0d': < ResourceRef 'Storage.fbe886d2-c61a-4f97-818c-528ac5e0ca0d', isValid: 'True' obj: 'None'>}
>Thread-141::DEBUG::2014-05-16 15:30:51,094::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-141::DEBUG::2014-05-16 15:30:51,094::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.fbe886d2-c61a-4f97-818c-528ac5e0ca0d'
>Thread-141::DEBUG::2014-05-16 15:30:51,094::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.fbe886d2-c61a-4f97-818c-528ac5e0ca0d' (0 active users)
>Thread-141::DEBUG::2014-05-16 15:30:51,094::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.fbe886d2-c61a-4f97-818c-528ac5e0ca0d' is free, finding out if anyone is waiting for it.
>Thread-141::DEBUG::2014-05-16 15:30:51,094::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.fbe886d2-c61a-4f97-818c-528ac5e0ca0d', Clearing records.
>Thread-141::DEBUG::2014-05-16 15:30:51,094::task::993::TaskManager.Task::(_decref) Task=`eb9a173d-2a53-444e-84de-95508c427398`::ref 0 aborting False
>Thread-141::INFO::2014-05-16 15:30:51,094::clientIF::313::vds::(prepareVolumePath) prepared volume path: /rhev/data-center/mnt/dellserver.home:_home_images/fbe886d2-c61a-4f97-818c-528ac5e0ca0d/images/fca201d2-7a8f-405e-953e-d7fe10456fde/c79ca92e-abce-4fed-85f6-e7702f19f04a
>Thread-141::DEBUG::2014-05-16 15:30:51,102::vm::2834::vm.Vm::(_run) vmId=`9e33ca94-1cf7-4791-b063-c4709482f691`::<?xml version="1.0" encoding="utf-8"?>
><domain type="kvm">
>	<name>test</name>
>	<uuid>9e33ca94-1cf7-4791-b063-c4709482f691</uuid>
>	<memory>1048576</memory>
>	<currentMemory>1048576</currentMemory>
>	<vcpu current="1">160</vcpu>
>	<memtune>
>		<min_guarantee>1048576</min_guarantee>
>	</memtune>
>	<devices>
>		<channel type="unix">
>			<target name="com.redhat.rhevm.vdsm" type="virtio"/>
>			<source mode="bind" path="/var/lib/libvirt/qemu/channels/9e33ca94-1cf7-4791-b063-c4709482f691.com.redhat.rhevm.vdsm"/>
>		</channel>
>		<channel type="unix">
>			<target name="org.qemu.guest_agent.0" type="virtio"/>
>			<source mode="bind" path="/var/lib/libvirt/qemu/channels/9e33ca94-1cf7-4791-b063-c4709482f691.org.qemu.guest_agent.0"/>
>		</channel>
>		<input bus="ps2" type="mouse"/>
>		<channel type="spicevmc">
>			<target name="com.redhat.spice.0" type="virtio"/>
>		</channel>
>		<graphics autoport="yes" keymap="en-us" listen="0" passwd="*****" passwdValidTo="1970-01-01T00:00:01" port="-1" tlsPort="-1" type="spice">
>			<channel mode="secure" name="main"/>
>			<channel mode="secure" name="inputs"/>
>			<channel mode="secure" name="cursor"/>
>			<channel mode="secure" name="playback"/>
>			<channel mode="secure" name="record"/>
>			<channel mode="secure" name="display"/>
>			<channel mode="secure" name="usbredir"/>
>			<channel mode="secure" name="smartcard"/>
>		</graphics>
>		<memballoon model="none"/>
>		<controller index="0" model="virtio-scsi" type="scsi"/>
>		<video>
>			<model heads="1" type="qxl" vram="32768"/>
>		</video>
>		<interface type="bridge">
>			<mac address="00:1A:4A:B2:A2:50"/>
>			<model type="virtio"/>
>			<source bridge="ovirtmgmt"/>
>			<filterref filter="vdsm-no-mac-spoofing"/>
>			<link state="up"/>
>		</interface>
>		<disk device="cdrom" snapshot="no" type="file">
>			<source file="/rhev/data-center/mnt/dellserver.home:_var_lib_exports_iso-20140516130700/cdd53e08-b51b-4ce9-b508-180e7c0be7d2/images/11111111-1111-1111-1111-111111111111/f19.iso" startupPolicy="optional"/>
>			<target bus="ide" dev="hdc"/>
>			<readonly/>
>			<serial/>
>			<boot order="1"/>
>		</disk>
>		<disk device="disk" snapshot="no" type="file">
>			<source file="/rhev/data-center/mnt/dellserver.home:_home_images/fbe886d2-c61a-4f97-818c-528ac5e0ca0d/images/fca201d2-7a8f-405e-953e-d7fe10456fde/c79ca92e-abce-4fed-85f6-e7702f19f04a"/>
>			<target bus="virtio" dev="vda"/>
>			<serial>fca201d2-7a8f-405e-953e-d7fe10456fde</serial>
>			<driver cache="none" error_policy="stop" io="threads" name="qemu" type="raw"/>
>		</disk>
>	</devices>
>	<os>
>		<type arch="x86_64" machine="pc-1.0">hvm</type>
>		<smbios mode="sysinfo"/>
>	</os>
>	<sysinfo type="smbios">
>		<system>
>			<entry name="manufacturer">oVirt</entry>
>			<entry name="product">oVirt Node</entry>
>			<entry name="version">19-8</entry>
>			<entry name="serial">4C4C4544-0059-4310-8035-C4C04F595831</entry>
>			<entry name="uuid">9e33ca94-1cf7-4791-b063-c4709482f691</entry>
>		</system>
>	</sysinfo>
>	<clock adjustment="0" offset="variable">
>		<timer name="rtc" tickpolicy="catchup"/>
>		<timer name="pit" tickpolicy="delay"/>
>		<timer name="hpet" present="no"/>
>	</clock>
>	<features>
>		<acpi/>
>	</features>
>	<cpu match="exact">
>		<model>Westmere</model>
>		<topology cores="1" sockets="160" threads="1"/>
>	</cpu>
>	<numatune>
>		<memory mode="preferred" nodeset=""/>
>	</numatune>
></domain>
>
>Thread-141::DEBUG::2014-05-16 15:30:51,103::libvirtconnection::125::root::(wrapper) Unknown libvirterror: ecode: 8 edom: 0 level: 2 message: invalid argument: Failed to parse bitmap ''
>Thread-141::DEBUG::2014-05-16 15:30:51,103::vm::1951::vm.Vm::(_startUnderlyingVm) vmId=`9e33ca94-1cf7-4791-b063-c4709482f691`::_ongoingCreations released
>Thread-141::ERROR::2014-05-16 15:30:51,104::vm::1989::vm.Vm::(_startUnderlyingVm) vmId=`9e33ca94-1cf7-4791-b063-c4709482f691`::The vm start process failed
>Traceback (most recent call last):
>  File "/usr/share/vdsm/virt/vm.py", line 1932, in _startUnderlyingVm
>    self._run()
>  File "/usr/share/vdsm/virt/vm.py", line 2868, in _run
>    self._connection.createXML(domxml, flags),
>  File "/usr/lib64/python2.7/site-packages/vdsm/libvirtconnection.py", line 93, in wrapper
>    ret = f(*args, **kwargs)
>  File "/usr/lib64/python2.7/site-packages/libvirt.py", line 2920, in createXML
>    if ret is None:raise libvirtError('virDomainCreateXML() failed', conn=self)
>libvirtError: invalid argument: Failed to parse bitmap ''
>Thread-141::DEBUG::2014-05-16 15:30:51,105::vm::2405::vm.Vm::(setDownStatus) vmId=`9e33ca94-1cf7-4791-b063-c4709482f691`::Changed state to Down: invalid argument: Failed to parse bitmap '' (code=1)

Actions: View

Attachments on bug 1098539: 896414 | 896415 | 896416