1:46 p.m.
------=_Part_14812387_1517716221.1383129966977
Content-Type: text/plain; charset=utf-8
Content-Transfer-Encoding: 7bit
----- Original Message -----
From: "Alessandro Bianchi" <a.bianchi(a)skynet.it>
To: users(a)ovirt.org
Sent: Wednesday, October 30, 2013 12:34:21 PM
Subject: [Users] Gluster VM stuck in "waiting for launch" state
Hi everyone
I've set up a gluster storage with two replicated bricks
DC is up and I created a VM to test gluster storage
If I start the VM WITHOUT any disk attached (only one virtual DVD) it
starts
fine.
If I attach a gluster domain disk thin provisioning 30 Gb the Vm
stucks in
"waiting for launch" state
I see no special activity on the gluster servers (they serve several
other
shares with no troubles at all and even the ISO domain is a NFS on locally
mounted gluster and works fine)
I've double checked all the pre requisites and they look fine (F
19 - gluster
setup insecure in both glusterd.vol and volume options - uid/gid/insecure )
Am I doing something wrong?
I'm even unable to stop the VM from the engine GUI
Any advise?
what is the status of the host that runs the vm?
is it up?
Thank you
Best regards
CentOS_30.log
2013-10-30 10:17:48.094+0000: starting up
LC_ALL=C PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin
QEMU_AUDIO_DRV=spice /usr/bin/qemu-kvm -name CentOS_30 -S -machine
pc-1.0,accel=kvm,usb=off -cpu Westmere -m 2048 -smp
1,sockets=1,cores=1,threads=1 -uuid 200dfb05-461e-49d9-95a2-c0a7c7ced669
-smbios type=1,manufacturer=oVirt,product=oVirt
Node,version=19-4,serial=316140A0-D7DA-11DD-AF75-08606ED667F7,uuid=200dfb05-461e-49d9-95a2-c0a7c7ced669
-no-user-config -nodefaults -chardev
socket,id=charmonitor,path=/var/lib/libvirt/qemu/CentOS_30.monitor,server,nowait
-mon chardev=charmonitor,id=monitor,mode=control -rtc
base=2013-10-30T10:17:47,driftfix=slew -no-shutdown -device
piix3-usb-uhci,id=usb,bus=pci.0,addr=0x1.0x2 -device
virtio-scsi-pci,id=scsi0,bus=pci.0,addr=0x4 -device
virtio-serial-pci,id=virtio-serial0,bus=pci.0,addr=0x5 -drive
file=/rhev/data-center/mnt/172.16.0.5:_home_iso2/8e56a914-3395-48ad-ab4c-c2ca7f9956b4/images/11111111-1111-1111-1111-111111111111/CentOS-6.4-x86_64-bin-DVD1.iso,if=none,id=drive-ide0-1-0,readonly=on,format=raw,serial=
-device ide-cd,bus=ide.1,unit=0,drive=drive-ide0-1-0,id=ide0-1-0,bootindex=1
-drive
file=gluster://172.16.0.100/vms/21e3d67f-fdec-4f87-b09e-53af994a6f87/images/b73a79fe-401b-434c-b023-6de4c3eb100d/202adc86-7857-40eb-8ca6-7cec3ef0d2d6,if=none,id=drive-virtio-disk0,format=raw,serial=b73a79fe-401b-434c-b023-6de4c3eb100d,cache=none,werror=stop,rerror=stop,aio=threads
-device
virtio-blk-pci,scsi=off,bus=pci.0,addr=0x6,drive=drive-virtio-disk0,id=virtio-disk0,bootindex=2
-netdev tap,fd=27,id=hostnet0,vhost=on,vhostfd=28 -device
virtio-net-pci,netdev=hostnet0,id=net0,mac=00:1a:4a:00:00:33,bus=pci.0,addr=0x3,bootindex=3
-chardev
socket,id=charchannel0,path=/var/lib/libvirt/qemu/channels/200dfb05-461e-49d9-95a2-c0a7c7ced669.com.redhat.rhevm.vdsm,server,nowait
-device
virtserialport,bus=virtio-serial0.0,nr=1,chardev=charchannel0,id=channel0,name=com.redhat.rhevm.vdsm
-chardev
socket,id=charchannel1,path=/var/lib/libvirt/qemu/channels/200dfb05-461e-49d9-95a2-c0a7c7ced669.org.qemu.guest_agent.0,server,nowait
-device
virtserialport,bus=virtio-serial0.0,nr=2,chardev=charchannel1,id=channel1,name=org.qemu.guest_agent.0
-chardev spicevmc,id=charchannel2,name=vdagent -device
virtserialport,bus=virtio-serial0.0,nr=3,chardev=charchannel2,id=channel2,name=com.redhat.spice.0
-spice
tls-port=5900,addr=0,x509-dir=/etc/pki/vdsm/libvirt-spice,tls-channel=main,tls-channel=display,tls-channel=inputs,tls-channel=cursor,tls-channel=playback,tls-channel=record,tls-channel=smartcard,tls-channel=usbredir,seamless-migration=on
-k en-us -vga qxl -global qxl-vga.ram_size=67108864 -global
qxl-vga.vram_size=67108864 -device virtio-balloon-pci,id=balloon0,bus=pci
vdsm.log
Thread-1239::DEBUG::2013-10-30
11:25:03,420::task::974::TaskManager.Task::(_decref)
Task=`d891f3d3-070d-403f-9050-f10651a7fc47`::ref 0 aborting False
Thread-242::DEBUG::2013-10-30
11:25:04,982::domainMonitor::178::Storage.DomainMonitorThread::(_monitorDomain)
Refreshing domain 21e3d67f-fdec-4f87-b09e-53af994a6f87
Thread-242::DEBUG::2013-10-30
11:25:04,992::fileSD::153::Storage.StorageDomain::(__init__) Reading domain
in path
/rhev/data-center/mnt/glusterSD/172.16.0.100:vms/21e3d67f-fdec-4f87-b09e-53af994a6f87
Thread-242::DEBUG::2013-10-30
11:25:04,994::persistentDict::192::Storage.PersistentDict::(__init__)
Created a persistent dict with FileMetadataRW backend
Thread-242::DEBUG::2013-10-30
11:25:05,005::persistentDict::234::Storage.PersistentDict::(refresh) read
lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=vms',
'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60',
'LOCKPOLICY=',
'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1',
'POOL_DESCRIPTION=GlusterSD',
'POOL_DOMAINS=21e3d67f-fdec-4f87-b09e-53af994a6f87:Active,8e56a914-3395-48ad-ab4c-c2ca7f9956b4:Active',
'POOL_SPM_ID=1', 'POOL_SPM_LVER=3',
'POOL_UUID=e3cb7694-47f7-4eac-9201-922e381a25dc',
'REMOTE_PATH=172.16.0.100:vms', 'ROLE=Master',
'SDUUID=21e3d67f-fdec-4f87-b09e-53af994a6f87', 'TYPE=GLUSTERFS',
'VERSION=3', '_SHA_CKSUM=2d0dc3836063d45dd1d8046aaf00bce05c2455ea']
Thread-242::DEBUG::2013-10-30
11:25:05,008::fileSD::535::Storage.StorageDomain::(imageGarbageCollector)
Removing remnants of deleted images []
Thread-242:: INFO::2013-10-30
11:25:05,008::sd::374::Storage.StorageDomain::(_registerResourceNamespaces)
Resource namespace 21e3d67f-fdec-4f87-b09e-53af994a6f87_imageNS already
registered
Thread-242:: INFO::2013-10-30
11:25:05,008::sd::382::Storage.StorageDomain::(_registerResourceNamespaces)
Resource namespace 21e3d67f-fdec-4f87-b09e-53af994a6f87_volumeNS already
registered
Thread-242::DEBUG::2013-10-30
11:25:05,020::fileSD::238::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd
iflag=direct
if=/rhev/data-center/mnt/glusterSD/172.16.0.100:vms/21e3d67f-fdec-4f87-b09e-53af994a6f87/dom_md/metadata
bs=4096 count=1' (cwd None)
Thread-242::DEBUG::2013-10-30
11:25:05,026::fileSD::238::Storage.Misc.excCmd::(getReadDelay) SUCCESS:
<err> = '0+1 records in\n0+1 records out\n497 bytes (497 B) copied,
0.000280701 s, 1.8 MB/s\n'; <rc> = 0
Thread-243::DEBUG::2013-10-30
11:25:07,721::domainMonitor::178::Storage.DomainMonitorThread::(_monitorDomain)
Refreshing domain 8e56a914-3395-48ad-ab4c-c2ca7f9956b4
Thread-243::DEBUG::2013-10-30
11:25:07,730::fileSD::153::Storage.StorageDomain::(__init__) Reading domain
in path
/rhev/data-center/mnt/172.16.0.5:_home_iso2/8e56a914-3395-48ad-ab4c-c2ca7f9956b4
Thread-243::DEBUG::2013-10-30
11:25:07,731::persistentDict::192::Storage.PersistentDict::(__init__)
Created a persistent dict with FileMetadataRW backend
Thread-243::DEBUG::2013-10-30
11:25:07,740::persistentDict::234::Storage.PersistentDict::(refresh) read
lines (FileMetadataRW)=['CLASS=Iso', 'DESCRIPTION=ISO',
'IOOPTIMEOUTSEC=1',
'LEASERETRIES=3', 'LEASETIMESEC=5', 'LOCKPOLICY=',
'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=0',
'POOL_UUID=01b79582-75e3-436d-bade-db653207620b,e3cb7694-47f7-4eac-9201-922e381a25dc',
'REMOTE_PATH=172.16.0.5:/home/iso2', 'ROLE=Regular',
'SDUUID=8e56a914-3395-48ad-ab4c-c2ca7f9956b4', 'TYPE=NFS',
'VERSION=0',
'_SHA_CKSUM=b0d102325f279bb8efa68c594cbace0b11c66783']
Thread-243::DEBUG::2013-10-30
11:25:07,741::fileSD::535::Storage.StorageDomain::(imageGarbageCollector)
Removing remnants of deleted images []
Thread-243:: INFO::2013-10-30
11:25:07,741::sd::374::Storage.StorageDomain::(_registerResourceNamespaces)
Resource namespace 8e56a914-3395-48ad-ab4c-c2ca7f9956b4_imageNS already
registered
Thread-243:: INFO::2013-10-30
11:25:07,741::sd::382::Storage.StorageDomain::(_registerResourceNamespaces)
Resource namespace 8e56a914-3395-48ad-ab4c-c2ca7f9956b4_volumeNS already
registered
Thread-243::DEBUG::2013-10-30
11:25:07,757::fileSD::238::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd
iflag=direct
if=/rhev/data-center/mnt/172.16.0.5:_home_iso2/8e56a914-3395-48ad-ab4c-c2ca7f9956b4/dom_md/metadata
bs=4096 count=1' (cwd None)
Thread-243::DEBUG::2013-10-30
11:25:07,760::fileSD::238::Storage.Misc.excCmd::(getReadDelay) SUCCESS:
<err> = '0+1 records in\n0+1 records out\n373 bytes (373 B) copied,
0.000128829 s, 2.9 MB/s\n'; <rc> = 0
Thread-1246::DEBUG::2013-10-30
11:25:09,944::task::579::TaskManager.Task::(_updateState)
Task=`c064522b-6fe7-4cb2-b85d-ad1f8185919a`::moving from state init -> state
preparing
Thread-1246:: INFO::2013-10-30
11:25:09,944::logUtils::44::dispatcher::(wrapper) Run and protect:
repoStats(options=None)
Thread-1246:: INFO::2013-10-30
11:25:09,945::logUtils::47::dispatcher::(wrapper) Run and protect:
repoStats, Return response: {'21e3d67f-fdec-4f87-b09e-53af994a6f87':
{'delay': '0.000280701', 'lastCheck': '4.9',
'code': 0, 'valid': True,
'version': 3}, '8e56a914-3395-48ad-ab4c-c2ca7f9956b4': {'delay':
'0.000128829', 'lastCheck': '2.2', 'code': 0,
'valid': True, 'version': 0}}
Thread-1246::DEBUG::2013-10-30
11:25:09,945::task::1168::TaskManager.Task::(prepare)
Task=`c064522b-6fe7-4cb2-b85d-ad1f8185919a`::finished:
{'21e3d67f-fdec-4f87-b09e-53af994a6f87': {'delay':
'0.000280701',
'lastCheck': '4.9', 'code': 0, 'valid': True,
'version': 3},
'8e56a914-3395-48ad-ab4c-c2ca7f9956b4': {'delay': '0.000128829',
'lastCheck': '2.2', 'code': 0, 'valid': True,
'version': 0}}
Thread-1246::DEBUG::2013-10-30
11:25:09,945::task::579::TaskManager.Task::(_updateState)
Task=`c064522b-6fe7-4cb2-b85d-ad1f8185919a`::moving from state preparing ->
state finished
Thread-1246::DEBUG::2013-10-30
11:25:09,945::resourceManager::939::ResourceManager.Owner::(releaseAll)
Owner.releaseAll requests {} resources {}
Thread-1246::DEBUG::2013-10-30
11:25:09,945::resourceManager::976::ResourceManager.Owner::(cancelAll)
Owner.cancelAll requests {}
Thread-1246::DEBUG::2013-10-30
11:25:09,945::task::974::TaskManager.Task::(_decref)
Task=`c064522b-6fe7-4cb2-b85d-ad1f8185919a`::ref 0 aborting False
Thread-1249::DEBUG::2013-10-30
11:25:13,507::BindingXMLRPC::177::vds::(wrapper) client [172.16.0.5]
Thread-1249::DEBUG::2013-10-30
11:25:13,507::task::579::TaskManager.Task::(_updateState)
Task=`8518162d-eb91-44aa-819a-354e05807cb9`::moving from state init -> state
preparing
Thread-1249:: INFO::2013-10-30
11:25:13,507::logUtils::44::dispatcher::(wrapper) Run and protect:
getSpmStatus(spUUID='e3cb7694-47f7-4eac-9201-922e381a25dc', options=None)
Thread-1249:: INFO::2013-10-30
11:25:13,508::logUtils::47::dispatcher::(wrapper) Run and protect:
getSpmStatus, Return response: {'spm_st': {'spmId': 1,
'spmStatus': 'SPM',
'spmLver': 3}}
Thread-1249::DEBUG::2013-10-30
11:25:13,508::task::1168::TaskManager.Task::(prepare)
Task=`8518162d-eb91-44aa-819a-354e05807cb9`::finished: {'spm_st':
{'spmId':
1, 'spmStatus': 'SPM', 'spmLver': 3}}
Thread-1249::DEBUG::2013-10-30
11:25:13,508::task::579::TaskManager.Task::(_updateState)
Task=`8518162d-eb91-44aa-819a-354e05807cb9`::moving from state preparing ->
state finished
Thread-1249::DEBUG::2013-10-30
11:25:13,508::resourceManager::939::ResourceManager.Owner::(releaseAll)
Owner.releaseAll requests {} resources {}
Thread-1249::DEBUG::2013-10-30
11:25:13,508::resourceManager::976::ResourceManager.Owner::(cancelAll)
Owner.cancelAll requests {}
Thread-1249::DEBUG::2013-10-30
11:25:13,508::task::974::TaskManager.Task::(_decref)
Task=`8518162d-eb91-44aa-819a-354e05807cb9`::ref 0 aborting False
Thread-1250::DEBUG::2013-10-30
11:25:13,510::BindingXMLRPC::177::vds::(wrapper) client [172.16.0.5]
Thread-1250::DEBUG::2013-10-30
11:25:13,510::task::579::TaskManager.Task::(_updateState)
Task=`221b537a-2c1b-418f-93ff-bf77d4029097`::moving from state init -> state
preparing
Thread-1250:: INFO::2013-10-30
11:25:13,511::logUtils::44::dispatcher::(wrapper) Run and protect:
getStoragePoolInfo(spUUID='e3cb7694-47f7-4eac-9201-922e381a25dc',
options=None)
Thread-1250::DEBUG::2013-10-30
11:25:13,511::resourceManager::197::ResourceManager.Request::(__init__)
ResName=`Storage.e3cb7694-47f7-4eac-9201-922e381a25dc`ReqID=`42f323ef-aa03-49e6-893f-0e4ff0764b6b`::Request
was made in '/usr/share/vdsm/storage/hsm.py' line '2560' at
'getStoragePoolInfo'
Thread-1250::DEBUG::2013-10-30
11:25:13,511::resourceManager::541::ResourceManager::(registerResource)
Trying to register resource 'Storage.e3cb7694-47f7-4eac-9201-922e381a25dc'
for lock type 'shared'
Thread-1250::DEBUG::2013-10-30
11:25:13,511::resourceManager::600::ResourceManager::(registerResource)
Resource 'Storage.e3cb7694-47f7-4eac-9201-922e381a25dc' is free. Now locking
as 'shared' (1 active user)
Thread-1250::DEBUG::2013-10-30
11:25:13,511::resourceManager::237::ResourceManager.Request::(grant)
ResName=`Storage.e3cb7694-47f7-4eac-9201-922e381a25dc`ReqID=`42f323ef-aa03-49e6-893f-0e4ff0764b6b`::Granted
request
Thread-1250::DEBUG::2013-10-30
11:25:13,512::task::811::TaskManager.Task::(resourceAcquired)
Task=`221b537a-2c1b-418f-93ff-bf77d4029097`::_resourcesAcquired:
Storage.e3cb7694-47f7-4eac-9201-922e381a25dc (shared)
Thread-1250::DEBUG::2013-10-30
11:25:13,512::task::974::TaskManager.Task::(_decref)
Task=`221b537a-2c1b-418f-93ff-bf77d4029097`::ref 1 aborting False
Thread-1250:: INFO::2013-10-30
11:25:13,517::logUtils::47::dispatcher::(wrapper) Run and protect:
getStoragePoolInfo, Return response: {'info': {'spm_id': 1,
'master_uuid':
'21e3d67f-fdec-4f87-b09e-53af994a6f87', 'name': 'GlusterSD',
'version': '3',
'domains':
'21e3d67f-fdec-4f87-b09e-53af994a6f87:Active,8e56a914-3395-48ad-ab4c-c2ca7f9956b4:Active',
'pool_status': 'connected', 'isoprefix':
'/rhev/data-center/mnt/172.16.0.5:_home_iso2/8e56a914-3395-48ad-ab4c-c2ca7f9956b4/images/11111111-1111-1111-1111-111111111111',
'type': 'GLUSTERFS', 'master_ver': 1, 'lver': 3},
'dominfo':
{'21e3d67f-fdec-4f87-b09e-53af994a6f87': {'status': 'Active',
'diskfree':
'239969632256', 'alerts': [], 'version': 3, 'disktotal':
'492120440832'},
'8e56a914-3395-48ad-ab4c-c2ca7f9956b4': {'status': 'Active',
'diskfree':
'201653747712', 'alerts': [], 'version': 0, 'disktotal':
'246783410176'}}}
Thread-1250::DEBUG::2013-10-30
11:25:13,517::task::1168::TaskManager.Task::(prepare)
Task=`221b537a-2c1b-418f-93ff-bf77d4029097`::finished: {'info':
{'spm_id':
1, 'master_uuid': '21e3d67f-fdec-4f87-b09e-53af994a6f87',
'name':
'GlusterSD', 'version': '3', 'domains':
'21e3d67f-fdec-4f87-b09e-53af994a6f87:Active,8e56a914-3395-48ad-ab4c-c2ca7f9956b4:Active',
'pool_status': 'connected', 'isoprefix':
'/rhev/data-center/mnt/172.16.0.5:_home_iso2/8e56a914-3395-48ad-ab4c-c2ca7f9956b4/images/11111111-1111-1111-1111-111111111111',
'type': 'GLUSTERFS', 'master_ver': 1, 'lver': 3},
'dominfo':
{'21e3d67f-fdec-4f87-b09e-53af994a6f87': {'status': 'Active',
'diskfree':
'239969632256', 'alerts': [], 'version': 3, 'disktotal':
'492120440832'},
'8e56a914-3395-48ad-ab4c-c2ca7f9956b4': {'status': 'Active',
'diskfree':
'201653747712', 'alerts': [], 'version': 0, 'disktotal':
'246783410176'}}}
Thread-1250::DEBUG::2013-10-30
11:25:13,517::task::579::TaskManager.Task::(_updateState)
Task=`221b537a-2c1b-418f-93ff-bf77d4029097`::moving from state preparing ->
state finished
Thread-1250::DEBUG::2013-10-30
11:25:13,517::resourceManager::939::ResourceManager.Owner::(releaseAll)
Owner.releaseAll requests {} resources
{'Storage.e3cb7694-47f7-4eac-9201-922e381a25dc': < ResourceRef
'Storage.e3cb7694-47f7-4eac-9201-922e381a25dc', isValid: 'True' obj:
'None'>}
Thread-1250::DEBUG::2013-10-30
11:25:13,518::resourceManager::976::ResourceManager.Owner::(cancelAll)
Owner.cancelAll requests {}
Thread-1250::DEBUG::2013-10-30
11:25:13,518::resourceManager::615::ResourceManager::(releaseResource)
Trying to release resource 'Storage.e3cb7694-47f7-4eac-9201-922e381a25dc'
Thread-1250::DEBUG::2013-10-30
11:25:13,518::resourceManager::634::ResourceManager::(releaseResource)
Released resource 'Storage.e3cb7694-47f7-4eac-9201-922e381a25dc' (0 active
users)
Thread-1250::DEBUG::2013-10-30
11:25:13,518::resourceManager::640::ResourceManager::(releaseResource)
Resource 'Storage.e3cb7694-47f7-4eac-9201-922e381a25dc' is free, finding out
if anyone is waiting for it.
Thread-1250::DEBUG::2013-10-30
11:25:13,518::resourceManager::648::ResourceManager::(releaseResource) No
one is waiting for resource 'Storage.e3cb7694-47f7-4eac-9201-922e381a25dc',
Clearing records.
Thread-1250::DEBUG::2013-10-30
11:25:13,518::task::974::TaskManager.Task::(_decref)
Task=`221b537a-2c1b-418f-93ff-bf77d4029097`::ref 0 aborting False
Thread-242::DEBUG::2013-10-30
11:25:15,046::fileSD::238::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd
iflag=direct
if=/rhev/data-center/mnt/glusterSD/172.16.0.100:vms/21e3d67f-fdec-4f87-b09e-53af994a6f87/dom_md/metadata
bs=4096 count=1' (cwd None)
Thread-242::DEBUG::2013-10-30
11:25:15,051::fileSD::238::Storage.Misc.excCmd::(getReadDelay) SUCCESS:
<err> = '0+1 records in\n0+1 records out\n497 bytes (497 B) copied,
0.00032077 s, 1.5 MB/s\n'; <rc> = 0
Thread-243::DEBUG::2013-10-30
11:25:17,777::fileSD::238::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd
iflag=direct
if=/rhev/data-center/mnt/172.16.0.5:_home_iso2/8e56a914-3395-48ad-ab4c-c2ca7f9956b4/dom_md/metadata
bs=4096 count=1' (cwd None)
Thread-243::DEBUG::2013-10-30
11:25:17,780::fileSD::238::Storage.Misc.excCmd::(getReadDelay) SUCCESS:
<err> = '0+1 records in\n0+1 records out\n373 bytes (373 B) copied,
9.9232e-05 s, 3.8 Thread-1239::DEBUG::2013-10-30
11:25:03,420::task::974::TaskManager.Task::(_decref)
Task=`d891f3d3-070d-403f-9050-f10651a7fc47`::ref 0 aborting False
Thread-242::DEBUG::2013-10-30
11:25:04,982::domainMonitor::178::Storage.DomainMonitorThread::(_monitorDomain)
Refreshing domain 21e3d67f-fdec-4f87-b09e-53af994a6f87
Thread-242::DEBUG::2013-10-30
11:25:04,992::fileSD::153::Storage.StorageDomain::(__init__) Reading domain
in path
/rhev/data-center/mnt/glusterSD/172.16.0.100:vms/21e3d67f-fdec-4f87-b09e-53af994a6f87
Thread-242::DEBUG::2013-10-30
11:25:04,994::persistentDict::192::Storage.PersistentDict::(__init__)
Created a persistent dict with FileMetadataRW backend
Thread-242::DEBUG::2013-10-30
11:25:05,005::persistentDict::234::Storage.PersistentDict::(refresh) read
lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=vms',
'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60',
'LOCKPOLICY=',
'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1',
'POOL_DESCRIPTION=GlusterSD',
'POOL_DOMAINS=21e3d67f-fdec-4f87-b09e-53af994a6f87:Active,8e56a914-3395-48ad-ab4c-c2ca7f9956b4:Active',
'POOL_SPM_ID=1', 'POOL_SPM_LVER=3',
'POOL_UUID=e3cb7694-47f7-4eac-9201-922e381a25dc',
'REMOTE_PATH=172.16.0.100:vms', 'ROLE=Master',
'SDUUID=21e3d67f-fdec-4f87-b09e-53af994a6f87', 'TYPE=GLUSTERFS',
'VERSION=3', '_SHA_CKSUM=2d0dc3836063d45dd1d8046aaf00bce05c2455ea']
Thread-242::DEBUG::2013-10-30
11:25:05,008::fileSD::535::Storage.StorageDomain::(imageGarbageCollector)
Removing remnants of deleted images []
Thread-242:: INFO::2013-10-30
11:25:05,008::sd::374::Storage.StorageDomain::(_registerResourceNamespaces)
Resource namespace 21e3d67f-fdec-4f87-b09e-53af994a6f87_imageNS already
registered
Thread-242:: INFO::2013-10-30
11:25:05,008::sd::382::Storage.StorageDomain::(_registerResourceNamespaces)
Resource namespace 21e3d67f-fdec-4f87-b09e-53af994a6f87_volumeNS already
registered
Thread-242::DEBUG::2013-10-30
11:25:05,020::fileSD::238::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd
iflag=direct
if=/rhev/data-center/mnt/glusterSD/172.16.0.100:vms/21e3d67f-fdec-4f87-b09e-53af994a6f87/dom_md/metadata
bs=4096 count=1' (cwd None)
Thread-242::DEBUG::2013-10-30
11:25:05,026::fileSD::238::Storage.Misc.excCmd::(getReadDelay) SUCCESS:
<err> = '0+1 records in\n0+1 records out\n497 bytes (497 B) copied,
0.000280701 s, 1.8 MB/s\n'; <rc> = 0
Thread-243::DEBUG::2013-10-30
11:25:07,721::domainMonitor::178::Storage.DomainMonitorThread::(_monitorDomain)
Refreshing domain 8e56a914-3395-48ad-ab4c-c2ca7f9956b4
Thread-243::DEBUG::2013-10-30
11:25:07,730::fileSD::153::Storage.StorageDomain::(__init__) Reading domain
in path
/rhev/data-center/mnt/172.16.0.5:_home_iso2/8e56a914-3395-48ad-ab4c-c2ca7f9956b4
Thread-243::DEBUG::2013-10-30
11:25:07,731::persistentDict::192::Storage.PersistentDict::(__init__)
Created a persistent dict with FileMetadataRW backend
Thread-243::DEBUG::2013-10-30
11:25:07,740::persistentDict::234::Storage.PersistentDict::(refresh) read
lines (FileMetadataRW)=['CLASS=Iso', 'DESCRIPTION=ISO',
'IOOPTIMEOUTSEC=1',
'LEASERETRIES=3', 'LEASETIMESEC=5', 'LOCKPOLICY=',
'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=0',
'POOL_UUID=01b79582-75e3-436d-bade-db653207620b,e3cb7694-47f7-4eac-9201-922e381a25dc',
'REMOTE_PATH=172.16.0.5:/home/iso2', 'ROLE=Regular',
'SDUUID=8e56a914-3395-48ad-ab4c-c2ca7f9956b4', 'TYPE=NFS',
'VERSION=0',
'_SHA_CKSUM=b0d102325f279bb8efa68c594cbace0b11c66783']
Thread-243::DEBUG::2013-10-30
11:25:07,741::fileSD::535::Storage.StorageDomain::(imageGarbageCollector)
Removing remnants of deleted images []
Thread-243:: INFO::2013-10-30
11:25:07,741::sd::374::Storage.StorageDomain::(_registerResourceNamespaces)
Resource namespace 8e56a914-3395-48ad-ab4c-c2ca7f9956b4_imageNS already
registered
Thread-243:: INFO::2013-10-30
11:25:07,741::sd::382::Storage.StorageDomain::(_registerResourceNamespaces)
Resource namespace 8e56a914-3395-48ad-ab4c-c2ca7f9956b4_volumeNS already
registered
Thread-243::DEBUG::2013-10-30
11:25:07,757::fileSD::238::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd
iflag=direct
if=/rhev/data-center/mnt/172.16.0.5:_home_iso2/8e56a914-3395-48ad-ab4c-c2ca7f9956b4/dom_md/metadata
bs=4096 count=1' (cwd None)
Thread-243::DEBUG::2013-10-30
11:25:07,760::fileSD::238::Storage.Misc.excCmd::(getReadDelay) SUCCESS:
<err> = '0+1 records in\n0+1 records out\n373 bytes (373 B) copied,
0.000128829 s, 2.9 MB/s\n'; <rc> = 0
Thread-1246::DEBUG::2013-10-30
11:25:09,944::task::579::TaskManager.Task::(_updateState)
Task=`c064522b-6fe7-4cb2-b85d-ad1f8185919a`::moving from state init -> state
preparing
Thread-1246:: INFO::2013-10-30
11:25:09,944::logUtils::44::dispatcher::(wrapper) Run and protect:
repoStats(options=None)
Thread-1246:: INFO::2013-10-30
11:25:09,945::logUtils::47::dispatcher::(wrapper) Run and protect:
repoStats, Return response: {'21e3d67f-fdec-4f87-b09e-53af994a6f87':
{'delay': '0.000280701', 'lastCheck': '4.9',
'code': 0, 'valid': True,
'version': 3}, '8e56a914-3395-48ad-ab4c-c2ca7f9956b4': {'delay':
'0.000128829', 'lastCheck': '2.2', 'code': 0,
'valid': True, 'version': 0}}
Thread-1246::DEBUG::2013-10-30
11:25:09,945::task::1168::TaskManager.Task::(prepare)
Task=`c064522b-6fe7-4cb2-b85d-ad1f8185919a`::finished:
{'21e3d67f-fdec-4f87-b09e-53af994a6f87': {'delay':
'0.000280701',
'lastCheck': '4.9', 'code': 0, 'valid': True,
'version': 3},
'8e56a914-3395-48ad-ab4c-c2ca7f9956b4': {'delay': '0.000128829',
'lastCheck': '2.2', 'code': 0, 'valid': True,
'version': 0}}
Thread-1246::DEBUG::2013-10-30
11:25:09,945::task::579::TaskManager.Task::(_updateState)
Task=`c064522b-6fe7-4cb2-b85d-ad1f8185919a`::moving from state preparing ->
state finished
Thread-1246::DEBUG::2013-10-30
11:25:09,945::resourceManager::939::ResourceManager.Owner::(releaseAll)
Owner.releaseAll requests {} resources {}
Thread-1246::DEBUG::2013-10-30
11:25:09,945::resourceManager::976::ResourceManager.Owner::(cancelAll)
Owner.cancelAll requests {}
Thread-1246::DEBUG::2013-10-30
11:25:09,945::task::974::TaskManager.Task::(_decref)
Task=`c064522b-6fe7-4cb2-b85d-ad1f8185919a`::ref 0 aborting False
Thread-1249::DEBUG::2013-10-30
11:25:13,507::BindingXMLRPC::177::vds::(wrapper) client [172.16.0.5]
Thread-1249::DEBUG::2013-10-30
11:25:13,507::task::579::TaskManager.Task::(_updateState)
Task=`8518162d-eb91-44aa-819a-354e05807cb9`::moving from state init -> state
preparing
Thread-1249:: INFO::2013-10-30
11:25:13,507::logUtils::44::dispatcher::(wrapper) Run and protect:
getSpmStatus(spUUID='e3cb7694-47f7-4eac-9201-922e381a25dc', options=None)
Thread-1249:: INFO::2013-10-30
11:25:13,508::logUtils::47::dispatcher::(wrapper) Run and protect:
getSpmStatus, Return response: {'spm_st': {'spmId': 1,
'spmStatus': 'SPM',
'spmLver': 3}}
Thread-1249::DEBUG::2013-10-30
11:25:13,508::task::1168::TaskManager.Task::(prepare)
Task=`8518162d-eb91-44aa-819a-354e05807cb9`::finished: {'spm_st':
{'spmId':
1, 'spmStatus': 'SPM', 'spmLver': 3}}
Thread-1249::DEBUG::2013-10-30
11:25:13,508::task::579::TaskManager.Task::(_updateState)
Task=`8518162d-eb91-44aa-819a-354e05807cb9`::moving from state preparing ->
state finished
Thread-1249::DEBUG::2013-10-30
11:25:13,508::resourceManager::939::ResourceManager.Owner::(releaseAll)
Owner.releaseAll requests {} resources {}
Thread-1249::DEBUG::2013-10-30
11:25:13,508::resourceManager::976::ResourceManager.Owner::(cancelAll)
Owner.cancelAll requests {}
Thread-1249::DEBUG::2013-10-30
11:25:13,508::task::974::TaskManager.Task::(_decref)
Task=`8518162d-eb91-44aa-819a-354e05807cb9`::ref 0 aborting False
Thread-1250::DEBUG::2013-10-30
11:25:13,510::BindingXMLRPC::177::vds::(wrapper) client [172.16.0.5]
Thread-1250::DEBUG::2013-10-30
11:25:13,510::task::579::TaskManager.Task::(_updateState)
Task=`221b537a-2c1b-418f-93ff-bf77d4029097`::moving from state init -> state
preparing
Thread-1250:: INFO::2013-10-30
11:25:13,511::logUtils::44::dispatcher::(wrapper) Run and protect:
getStoragePoolInfo(spUUID='e3cb7694-47f7-4eac-9201-922e381a25dc',
options=None)
Thread-1250::DEBUG::2013-10-30
11:25:13,511::resourceManager::197::ResourceManager.Request::(__init__)
ResName=`Storage.e3cb7694-47f7-4eac-9201-922e381a25dc`ReqID=`42f323ef-aa03-49e6-893f-0e4ff0764b6b`::Request
was made in '/usr/share/vdsm/storage/hsm.py' line '2560' at
'getStoragePoolInfo'
Thread-1250::DEBUG::2013-10-30
11:25:13,511::resourceManager::541::ResourceManager::(registerResource)
Trying to register resource 'Storage.e3cb7694-47f7-4eac-9201-922e381a25dc'
for lock type 'shared'
Thread-1250::DEBUG::2013-10-30
11:25:13,511::resourceManager::600::ResourceManager::(registerResource)
Resource 'Storage.e3cb7694-47f7-4eac-9201-922e381a25dc' is free. Now locking
as 'shared' (1 active user)
Thread-1250::DEBUG::2013-10-30
11:25:13,511::resourceManager::237::ResourceManager.Request::(grant)
ResName=`Storage.e3cb7694-47f7-4eac-9201-922e381a25dc`ReqID=`42f323ef-aa03-49e6-893f-0e4ff0764b6b`::Granted
request
Thread-1250::DEBUG::2013-10-30
11:25:13,512::task::811::TaskManager.Task::(resourceAcquired)
Task=`221b537a-2c1b-418f-93ff-bf77d4029097`::_resourcesAcquired:
Storage.e3cb7694-47f7-4eac-9201-922e381a25dc (shared)
Thread-1250::DEBUG::2013-10-30
11:25:13,512::task::974::TaskManager.Task::(_decref)
Task=`221b537a-2c1b-418f-93ff-bf77d4029097`::ref 1 aborting False
Thread-1250:: INFO::2013-10-30
11:25:13,517::logUtils::47::dispatcher::(wrapper) Run and protect:
getStoragePoolInfo, Return response: {'info': {'spm_id': 1,
'master_uuid':
'21e3d67f-fdec-4f87-b09e-53af994a6f87', 'name': 'GlusterSD',
'version': '3',
'domains':
'21e3d67f-fdec-4f87-b09e-53af994a6f87:Active,8e56a914-3395-48ad-ab4c-c2ca7f9956b4:Active',
'pool_status': 'connected', 'isoprefix':
'/rhev/data-center/mnt/172.16.0.5:_home_iso2/8e56a914-3395-48ad-ab4c-c2ca7f9956b4/images/11111111-1111-1111-1111-111111111111',
'type': 'GLUSTERFS', 'master_ver': 1, 'lver': 3},
'dominfo':
{'21e3d67f-fdec-4f87-b09e-53af994a6f87': {'status': 'Active',
'diskfree':
'239969632256', 'alerts': [], 'version': 3, 'disktotal':
'492120440832'},
'8e56a914-3395-48ad-ab4c-c2ca7f9956b4': {'status': 'Active',
'diskfree':
'201653747712', 'alerts': [], 'version': 0, 'disktotal':
'246783410176'}}}
Thread-1250::DEBUG::2013-10-30
11:25:13,517::task::1168::TaskManager.Task::(prepare)
Task=`221b537a-2c1b-418f-93ff-bf77d4029097`::finished: {'info':
{'spm_id':
1, 'master_uuid': '21e3d67f-fdec-4f87-b09e-53af994a6f87',
'name':
'GlusterSD', 'version': '3', 'domains':
'21e3d67f-fdec-4f87-b09e-53af994a6f87:Active,8e56a914-3395-48ad-ab4c-c2ca7f9956b4:Active',
'pool_status': 'connected', 'isoprefix':
'/rhev/data-center/mnt/172.16.0.5:_home_iso2/8e56a914-3395-48ad-ab4c-c2ca7f9956b4/images/11111111-1111-1111-1111-111111111111',
'type': 'GLUSTERFS', 'master_ver': 1, 'lver': 3},
'dominfo':
{'21e3d67f-fdec-4f87-b09e-53af994a6f87': {'status': 'Active',
'diskfree':
'239969632256', 'alerts': [], 'version': 3, 'disktotal':
'492120440832'},
'8e56a914-3395-48ad-ab4c-c2ca7f9956b4': {'status': 'Active',
'diskfree':
'201653747712', 'alerts': [], 'version': 0, 'disktotal':
'246783410176'}}}
Thread-1250::DEBUG::2013-10-30
11:25:13,517::task::579::TaskManager.Task::(_updateState)
Task=`221b537a-2c1b-418f-93ff-bf77d4029097`::moving from state preparing ->
state finished
Thread-1250::DEBUG::2013-10-30
11:25:13,517::resourceManager::939::ResourceManager.Owner::(releaseAll)
Owner.releaseAll requests {} resources
{'Storage.e3cb7694-47f7-4eac-9201-922e381a25dc': < ResourceRef
'Storage.e3cb7694-47f7-4eac-9201-922e381a25dc', isValid: 'True' obj:
'None'>}
Thread-1250::DEBUG::2013-10-30
11:25:13,518::resourceManager::976::ResourceManager.Owner::(cancelAll)
Owner.cancelAll requests {}
Thread-1250::DEBUG::2013-10-30
11:25:13,518::resourceManager::615::ResourceManager::(releaseResource)
Trying to release resource 'Storage.e3cb7694-47f7-4eac-9201-922e381a25dc'
Thread-1250::DEBUG::2013-10-30
11:25:13,518::resourceManager::634::ResourceManager::(releaseResource)
Released resource 'Storage.e3cb7694-47f7-4eac-9201-922e381a25dc' (0 active
users)
Thread-1250::DEBUG::2013-10-30
11:25:13,518::resourceManager::640::ResourceManager::(releaseResource)
Resource 'Storage.e3cb7694-47f7-4eac-9201-922e381a25dc' is free, finding out
if anyone is waiting for it.
Thread-1250::DEBUG::2013-10-30
11:25:13,518::resourceManager::648::ResourceManager::(releaseResource) No
one is waiting for resource 'Storage.e3cb7694-47f7-4eac-9201-922e381a25dc',
Clearing records.
Thread-1250::DEBUG::2013-10-30
11:25:13,518::task::974::TaskManager.Task::(_decref)
Task=`221b537a-2c1b-418f-93ff-bf77d4029097`::ref 0 aborting False
Thread-242::DEBUG::2013-10-30
11:25:15,046::fileSD::238::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd
iflag=direct
if=/rhev/data-center/mnt/glusterSD/172.16.0.100:vms/21e3d67f-fdec-4f87-b09e-53af994a6f87/dom_md/metadata
bs=4096 count=1' (cwd None)
Thread-242::DEBUG::2013-10-30
11:25:15,051::fileSD::238::Storage.Misc.excCmd::(getReadDelay) SUCCESS:
<err> = '0+1 records in\n0+1 records out\n497 bytes (497 B) copied,
0.00032077 s, 1.5 MB/s\n'; <rc> = 0
Thread-243::DEBUG::2013-10-30
11:25:17,777::fileSD::238::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd
iflag=direct
if=/rhev/data-center/mnt/172.16.0.5:_home_iso2/8e56a914-3395-48ad-ab4c-c2ca7f9956b4/dom_md/metadata
bs=4096 count=1' (cwd None)
Thread-243::DEBUG::2013-10-30
11:25:17,780::fileSD::238::Storage.Misc.excCmd::(getReadDelay) SUCCESS:
<err> = '0+1 records in\n0+1 records out\n373 bytes (373 B) copied,
9.9232e-05 s, 3.8 MB/s\n'; <rc> = 0
engine.log
2013-10-30 11:17:47,729 INFO
[org.ovirt.engine.core.bll.RunVmOnceCommand]
(ajp--127.0.0.1-8702-6) Running command: RunVmOnceCommand internal: false.
Entities affected : ID: 200dfb05-461e-49d9-95a2-c0a7c7ced669 Type: VM
2013-10-30 11:17:47,743 INFO
[org.ovirt.engine.core.vdsbroker.CreateVmVDSCommand] (ajp--127.0.0.1-8702-6)
START, CreateVmVDSCommand(HostName = Hypervisor, HostId =
da764821-0650-40f0-b7cf-038766fbd2ca,
vmId=200dfb05-461e-49d9-95a2-c0a7c7ced669, vm=VM [CentOS_30]), log id:
638a3a0e
2013-10-30 11:17:47,765 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand]
(ajp--127.0.0.1-8702-6) START, CreateVDSCommand(HostName = Hypervisor,
HostId = da764821-0650-40f0-b7cf-038766fbd2ca,
vmId=200dfb05-461e-49d9-95a2-c0a7c7ced669, vm=VM [CentOS_30]), log id:
297dbca2
2013-10-30 11:17:47,784 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand]
(ajp--127.0.0.1-8702-6)
org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand
spiceSslCipherSuite=DEFAULT,memSize=2048,kvmEnable=true,smp=1,vmType=kvm,emulatedMachine=pc-1.0,keyboardLayout=en-us,memGuaranteedSize=1365,pitReinjection=false,nice=0,display=qxl,smartcardEnable=false,smpCoresPerSocket=1,spiceSecureChannels=smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard,timeOffset=0,transparentHugePages=true,vmId=200dfb05-461e-49d9-95a2-c0a7c7ced669,devices=[Ljava.util.HashMap;@f3eee3e,acpiEnable=true,vmName=CentOS_30,cpuType=Westmere,custom={}
2013-10-30 11:17:47,785 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand]
(ajp--127.0.0.1-8702-6) FINISH, CreateVDSCommand, log id: 297dbca2
2013-10-30 11:17:47,786 INFO
[org.ovirt.engine.core.vdsbroker.CreateVmVDSCommand] (ajp--127.0.0.1-8702-6)
FINISH, CreateVmVDSCommand, return: WaitForLaunch, log id: 638a3a0e
2013-10-30 11:17:47,812 INFO
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(ajp--127.0.0.1-8702-6) Correlation ID: 4f8bc4f9, Job ID:
74a77fc0-7e83-44c0-b3d7-334eb38612b4, Call Stack: null, Custom Event ID: -1,
Message: VM CentOS_30 was started by admin@internal (Host: Hypervisor).
2013-10-30 11:17:51,115 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.FullListVdsCommand]
(DefaultQuartzScheduler_Worker-37) START, FullListVdsCommand(HostName =
Hypervisor, HostId = da764821-0650-40f0-b7cf-038766fbd2ca,
vds=Host[Hypervisor], vmIds=[200dfb05-461e-49d9-95a2-c0a7c7ced669]), log id:
546bd3e2
2013-10-30 11:17:51,119 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.FullListVdsCommand]
(DefaultQuartzScheduler_Worker-37) FINISH, FullListVdsCommand, return:
[Ljava.util.HashMap;@318a7164, log id: 546bd3e2
2013-10-30 11:17:51,121 INFO
[org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo]
(DefaultQuartzScheduler_Worker-37) Received a scsi Device without an address
when processing VM 200dfb05-461e-49d9-95a2-c0a7c7ced669 devices, skipping
device: {model=virtio-scsi, device=scsi, type=controller}
2013-10-30 11:17:51,121 INFO
[org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo]
(DefaultQuartzScheduler_Worker-37) Received a cdrom Device without an
address when processing VM 200dfb05-461e-49d9-95a2-c0a7c7ced669 devices,
skipping device: {shared=false, bootOrder=1, iface=ide, index=2,
specParams={}, device=cdrom,
path=/rhev/data-center/mnt/172.16.0.5:_home_iso2/8e56a914-3395-48ad-ab4c-c2ca7f9956b4/images/11111111-1111-1111-1111-111111111111/CentOS-6.4-x86_64-bin-DVD1.iso,
type=disk, readonly=true, deviceId=e29c7ac7-f872-43e3-90e2-cb2205c0203f}
2013-10-30 11:17:51,122 INFO
[org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo]
(DefaultQuartzScheduler_Worker-37) Received a disk Device without an address
when processing VM 200dfb05-461e-49d9-95a2-c0a7c7ced669 devices, skipping
device: {shared=false, volumeID=202adc86-7857-40eb-8ca6-7cec3ef0d2d6,
index=0, propagateErrors=off, format=raw, type=disk, truesize=4096,
reqsize=0, bootOrder=2, iface=virtio,
volumeChain=[Ljava.lang.Object;@8741843,
imageID=b73a79fe-401b-434c-b023-6de4c3eb100d,
domainID=21e3d67f-fdec-4f87-b09e-53af994a6f87, specParams={},
optional=false, volumeInfo={volfileServer=172.16.0.100, volPort=0,
protocol=gluster, volTransport=tcp,
path=vms/21e3d67f-fdec-4f87-b09e-53af994a6f87/images/b73a79fe-401b-434c-b023-6de4c3eb100d/202adc86-7857-40eb-8ca6-7cec3ef0d2d6,
volType=network},
path=/rhev/data-center/e3cb7694-47f7-4eac-9201-922e381a25dc/21e3d67f-fdec-4f87-b09e-53af994a6f87/images/b73a79fe-401b-434c-b023-6de4c3eb100d/202adc86-7857-40eb-8ca6-7cec3ef0d2d6,
device=disk, poolID=e3cb7694-47f7-4eac-9201-922e381a25dc, readonly=false,
deviceId=b73a79fe-401b-434c-b023-6de4c3eb100d, apparentsize=32212254720}
2013-10-30 11:17:51,123 INFO
[org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo]
(DefaultQuartzScheduler_Worker-37) Received a memballoon Device without an
address when processing VM 200dfb05-461e-49d9-95a2-c0a7c7ced669 devices,
skipping device: {specParams={model=virtio}, target=2097152,
device=memballoon, type=balloon,
deviceId=b61b058d-cdfe-4d7c-8e6c-1bfd631cb26c}
_______________________________________________
Users mailing list
Users(a)ovirt.org
http://lists.ovirt.org/mailman/listinfo/users
------=_Part_14812387_1517716221.1383129966977
Content-Type: text/html; charset=utf-8
Content-Transfer-Encoding: 7bit
<html><body><div style="font-family: times new roman, new york, times,
serif; font-size: 12pt; color:
#000000"><div><br></div><div><br></div><hr
id="zwchr"><blockquote style="border-left:2px solid
#1010FF;margin-left:5px;padding-left:5px;color:#000;font-weight:normal;font-style:normal;text-decoration:none;font-family:Helvetica,Arial,sans-serif;font-size:12pt;"><b>From:
</b>"Alessandro Bianchi"
&lt;a.bianchi(a)skynet.it&gt;<br><b>To:
</b>users(a)ovirt.org<br><b>Sent: </b>Wednesday, October 30, 2013
12:34:21 PM<br><b>Subject: </b>[Users] Gluster VM stuck in "waiting
for launch" state<br><div><br></div><div
id="QCMcontainer" style="font-family:sans-serif;font-size:16px;">Hi
everyone<br><br>
I've set up a gluster storage with two replicated bricks<br><br>
DC is up and I created a VM to test gluster storage<br><br>
If I start the VM WITHOUT any disk attached (only one virtual DVD)
it starts fine.<br><br>
If I attach a gluster domain disk thin provisioning 30 Gb the Vm
stucks in "waiting for launch" state<br><br>
I see no special activity on the gluster servers (they serve
several other shares with no troubles at all and even the ISO
domain is a NFS on locally mounted gluster and works
fine)<br><br>
I've double checked all the pre requisites and they look fine (F
19 - gluster setup insecure in both glusterd.vol and volume
options - uid/gid/insecure )<br><br>
Am I doing something wrong?<br><br>
I'm even unable to stop the VM from the engine GUI<br><br>
Any
advise?</div></blockquote><div><br></div><div>what is
the status of the host that runs the vm?<br></div><div>is it
up?<br></div><blockquote style="border-left:2px solid
#1010FF;margin-left:5px;padding-left:5px;color:#000;font-weight:normal;font-style:normal;text-decoration:none;font-family:Helvetica,Arial,sans-serif;font-size:12pt;"><div
id="QCMcontainer"
style="font-family:sans-serif;font-size:16px;"><br>
Thank you<br><br>
Best regards<br><br>
CentOS_30.log<br><br>
2013-10-30 10:17:48.094+0000: starting up<br>
LC_ALL=C PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin
QEMU_AUDIO_DRV=spice /usr/bin/qemu-kvm -name CentOS_30 -S -machine
pc-1.0,accel=kvm,usb=off -cpu Westmere -m 2048 -smp
1,sockets=1,cores=1,threads=1 -uuid
200dfb05-461e-49d9-95a2-c0a7c7ced669 -smbios
type=1,manufacturer=oVirt,product=oVirt
Node,version=19-4,serial=316140A0-D7DA-11DD-AF75-08606ED667F7,uuid=200dfb05-461e-49d9-95a2-c0a7c7ced669
-no-user-config -nodefaults -chardev
socket,id=charmonitor,path=/var/lib/libvirt/qemu/CentOS_30.monitor,server,nowait
-mon chardev=charmonitor,id=monitor,mode=control -rtc
base=2013-10-30T10:17:47,driftfix=slew -no-shutdown -device
piix3-usb-uhci,id=usb,bus=pci.0,addr=0x1.0x2 -device
virtio-scsi-pci,id=scsi0,bus=pci.0,addr=0x4 -device
virtio-serial-pci,id=virtio-serial0,bus=pci.0,addr=0x5 -drive
file=/rhev/data-center/mnt/172.16.0.5:_home_iso2/8e56a914-3395-48ad-ab4c-c2ca7f9956b4/images/11111111-1111-1111-1111-111111111111/CentOS-6.4-x86_64-bin-DVD1.iso,if=none,id=drive-ide0-1-0,readonly=on,format=raw,serial=
-device
ide-cd,bus=ide.1,unit=0,drive=drive-ide0-1-0,id=ide0-1-0,bootindex=1
-drive
file=gluster://172.16.0.100/vms/21e3d67f-fdec-4f87-b09e-53af994a6f87/images/b73a79fe-401b-434c-b023-6de4c3eb100d/202adc86-7857-40eb-8ca6-7cec3ef0d2d6,if=none,id=drive-virtio-disk0,format=raw,serial=b73a79fe-401b-434c-b023-6de4c3eb100d,cache=none,werror=stop,rerror=stop,aio=threads
-device
virtio-blk-pci,scsi=off,bus=pci.0,addr=0x6,drive=drive-virtio-disk0,id=virtio-disk0,bootindex=2
-netdev tap,fd=27,id=hostnet0,vhost=on,vhostfd=28 -device
virtio-net-pci,netdev=hostnet0,id=net0,mac=00:1a:4a:00:00:33,bus=pci.0,addr=0x3,bootindex=3
-chardev
socket,id=charchannel0,path=/var/lib/libvirt/qemu/channels/200dfb05-461e-49d9-95a2-c0a7c7ced669.com.redhat.rhevm.vdsm,server,nowait
-device
virtserialport,bus=virtio-serial0.0,nr=1,chardev=charchannel0,id=channel0,name=com.redhat.rhevm.vdsm
-chardev
socket,id=charchannel1,path=/var/lib/libvirt/qemu/channels/200dfb05-461e-49d9-95a2-c0a7c7ced669.org.qemu.guest_agent.0,server,nowait
-device
virtserialport,bus=virtio-serial0.0,nr=2,chardev=charchannel1,id=channel1,name=org.qemu.guest_agent.0
-chardev spicevmc,id=charchannel2,name=vdagent -device
virtserialport,bus=virtio-serial0.0,nr=3,chardev=charchannel2,id=channel2,name=com.redhat.spice.0
-spice
tls-port=5900,addr=0,x509-dir=/etc/pki/vdsm/libvirt-spice,tls-channel=main,tls-channel=display,tls-channel=inputs,tls-channel=cursor,tls-channel=playback,tls-channel=record,tls-channel=smartcard,tls-channel=usbredir,seamless-migration=on
-k en-us -vga qxl -global qxl-vga.ram_size=67108864 -global
qxl-vga.vram_size=67108864 -device
virtio-balloon-pci,id=balloon0,bus=pci<br><br>
vdsm.log<br><br>
Thread-1239::DEBUG::2013-10-30
11:25:03,420::task::974::TaskManager.Task::(_decref)
Task=`d891f3d3-070d-403f-9050-f10651a7fc47`::ref 0 aborting False<br>
Thread-242::DEBUG::2013-10-30
11:25:04,982::domainMonitor::178::Storage.DomainMonitorThread::(_monitorDomain)
Refreshing domain 21e3d67f-fdec-4f87-b09e-53af994a6f87<br>
Thread-242::DEBUG::2013-10-30
11:25:04,992::fileSD::153::Storage.StorageDomain::(__init__)
Reading domain in path
/rhev/data-center/mnt/glusterSD/172.16.0.100:vms/21e3d67f-fdec-4f87-b09e-53af994a6f87<br>
Thread-242::DEBUG::2013-10-30
11:25:04,994::persistentDict::192::Storage.PersistentDict::(__init__)
Created a persistent dict with FileMetadataRW backend<br>
Thread-242::DEBUG::2013-10-30
11:25:05,005::persistentDict::234::Storage.PersistentDict::(refresh)
read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=vms',
'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60',
'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5',
'MASTER_VERSION=1',
'POOL_DESCRIPTION=GlusterSD',
'POOL_DOMAINS=21e3d67f-fdec-4f87-b09e-53af994a6f87:Active,8e56a914-3395-48ad-ab4c-c2ca7f9956b4:Active',
'POOL_SPM_ID=1', 'POOL_SPM_LVER=3',
'POOL_UUID=e3cb7694-47f7-4eac-9201-922e381a25dc',
'REMOTE_PATH=172.16.0.100:vms', 'ROLE=Master',
'SDUUID=21e3d67f-fdec-4f87-b09e-53af994a6f87', 'TYPE=GLUSTERFS',
'VERSION=3',
'_SHA_CKSUM=2d0dc3836063d45dd1d8046aaf00bce05c2455ea']<br>
Thread-242::DEBUG::2013-10-30
11:25:05,008::fileSD::535::Storage.StorageDomain::(imageGarbageCollector)
Removing remnants of deleted images []<br>
Thread-242::<a class="moz-txt-link-freetext"
href="INFO::2013-10-30" target="_blank">INFO::2013-10-30</a>
11:25:05,008::sd::374::Storage.StorageDomain::(_registerResourceNamespaces)
Resource namespace 21e3d67f-fdec-4f87-b09e-53af994a6f87_imageNS
already registered<br>
Thread-242::<a class="moz-txt-link-freetext"
href="INFO::2013-10-30" target="_blank">INFO::2013-10-30</a>
11:25:05,008::sd::382::Storage.StorageDomain::(_registerResourceNamespaces)
Resource namespace 21e3d67f-fdec-4f87-b09e-53af994a6f87_volumeNS
already registered<br>
Thread-242::DEBUG::2013-10-30
11:25:05,020::fileSD::238::Storage.Misc.excCmd::(getReadDelay)
'/usr/bin/dd iflag=direct
if=/rhev/data-center/mnt/glusterSD/172.16.0.100:vms/21e3d67f-fdec-4f87-b09e-53af994a6f87/dom_md/metadata
bs=4096 count=1' (cwd None)<br>
Thread-242::DEBUG::2013-10-30
11:25:05,026::fileSD::238::Storage.Misc.excCmd::(getReadDelay)
SUCCESS: <err> = '0+1 records in\n0+1 records out\n497 bytes
(497 B) copied, 0.000280701 s, 1.8 MB/s\n'; <rc> = 0<br>
Thread-243::DEBUG::2013-10-30
11:25:07,721::domainMonitor::178::Storage.DomainMonitorThread::(_monitorDomain)
Refreshing domain 8e56a914-3395-48ad-ab4c-c2ca7f9956b4<br>
Thread-243::DEBUG::2013-10-30
11:25:07,730::fileSD::153::Storage.StorageDomain::(__init__)
Reading domain in path
/rhev/data-center/mnt/172.16.0.5:_home_iso2/8e56a914-3395-48ad-ab4c-c2ca7f9956b4<br>
Thread-243::DEBUG::2013-10-30
11:25:07,731::persistentDict::192::Storage.PersistentDict::(__init__)
Created a persistent dict with FileMetadataRW backend<br>
Thread-243::DEBUG::2013-10-30
11:25:07,740::persistentDict::234::Storage.PersistentDict::(refresh)
read lines (FileMetadataRW)=['CLASS=Iso', 'DESCRIPTION=ISO',
'IOOPTIMEOUTSEC=1', 'LEASERETRIES=3', 'LEASETIMESEC=5',
'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5',
'MASTER_VERSION=0',
'POOL_UUID=01b79582-75e3-436d-bade-db653207620b,e3cb7694-47f7-4eac-9201-922e381a25dc',
'REMOTE_PATH=172.16.0.5:/home/iso2', 'ROLE=Regular',
'SDUUID=8e56a914-3395-48ad-ab4c-c2ca7f9956b4', 'TYPE=NFS',
'VERSION=0',
'_SHA_CKSUM=b0d102325f279bb8efa68c594cbace0b11c66783']<br>
Thread-243::DEBUG::2013-10-30
11:25:07,741::fileSD::535::Storage.StorageDomain::(imageGarbageCollector)
Removing remnants of deleted images []<br>
Thread-243::<a class="moz-txt-link-freetext"
href="INFO::2013-10-30" target="_blank">INFO::2013-10-30</a>
11:25:07,741::sd::374::Storage.StorageDomain::(_registerResourceNamespaces)
Resource namespace 8e56a914-3395-48ad-ab4c-c2ca7f9956b4_imageNS
already registered<br>
Thread-243::<a class="moz-txt-link-freetext"
href="INFO::2013-10-30" target="_blank">INFO::2013-10-30</a>
11:25:07,741::sd::382::Storage.StorageDomain::(_registerResourceNamespaces)
Resource namespace 8e56a914-3395-48ad-ab4c-c2ca7f9956b4_volumeNS
already registered<br>
Thread-243::DEBUG::2013-10-30
11:25:07,757::fileSD::238::Storage.Misc.excCmd::(getReadDelay)
'/usr/bin/dd iflag=direct
if=/rhev/data-center/mnt/172.16.0.5:_home_iso2/8e56a914-3395-48ad-ab4c-c2ca7f9956b4/dom_md/metadata
bs=4096 count=1' (cwd None)<br>
Thread-243::DEBUG::2013-10-30
11:25:07,760::fileSD::238::Storage.Misc.excCmd::(getReadDelay)
SUCCESS: <err> = '0+1 records in\n0+1 records out\n373 bytes
(373 B) copied, 0.000128829 s, 2.9 MB/s\n'; <rc> = 0<br>
Thread-1246::DEBUG::2013-10-30
11:25:09,944::task::579::TaskManager.Task::(_updateState)
Task=`c064522b-6fe7-4cb2-b85d-ad1f8185919a`::moving from state
init -> state preparing<br>
Thread-1246::<a class="moz-txt-link-freetext"
href="INFO::2013-10-30" target="_blank">INFO::2013-10-30</a>
11:25:09,944::logUtils::44::dispatcher::(wrapper) Run and protect:
repoStats(options=None)<br>
Thread-1246::<a class="moz-txt-link-freetext"
href="INFO::2013-10-30" target="_blank">INFO::2013-10-30</a>
11:25:09,945::logUtils::47::dispatcher::(wrapper) Run and protect:
repoStats, Return response:
{'21e3d67f-fdec-4f87-b09e-53af994a6f87': {'delay':
'0.000280701',
'lastCheck': '4.9', 'code': 0, 'valid': True,
'version': 3},
'8e56a914-3395-48ad-ab4c-c2ca7f9956b4': {'delay':
'0.000128829',
'lastCheck': '2.2', 'code': 0, 'valid': True,
'version': 0}}<br>
Thread-1246::DEBUG::2013-10-30
11:25:09,945::task::1168::TaskManager.Task::(prepare)
Task=`c064522b-6fe7-4cb2-b85d-ad1f8185919a`::finished:
{'21e3d67f-fdec-4f87-b09e-53af994a6f87': {'delay':
'0.000280701',
'lastCheck': '4.9', 'code': 0, 'valid': True,
'version': 3},
'8e56a914-3395-48ad-ab4c-c2ca7f9956b4': {'delay':
'0.000128829',
'lastCheck': '2.2', 'code': 0, 'valid': True,
'version': 0}}<br>
Thread-1246::DEBUG::2013-10-30
11:25:09,945::task::579::TaskManager.Task::(_updateState)
Task=`c064522b-6fe7-4cb2-b85d-ad1f8185919a`::moving from state
preparing -> state finished<br>
Thread-1246::DEBUG::2013-10-30
11:25:09,945::resourceManager::939::ResourceManager.Owner::(releaseAll)
Owner.releaseAll requests {} resources {}<br>
Thread-1246::DEBUG::2013-10-30
11:25:09,945::resourceManager::976::ResourceManager.Owner::(cancelAll)
Owner.cancelAll requests {}<br>
Thread-1246::DEBUG::2013-10-30
11:25:09,945::task::974::TaskManager.Task::(_decref)
Task=`c064522b-6fe7-4cb2-b85d-ad1f8185919a`::ref 0 aborting False<br>
Thread-1249::DEBUG::2013-10-30
11:25:13,507::BindingXMLRPC::177::vds::(wrapper) client
[172.16.0.5]<br>
Thread-1249::DEBUG::2013-10-30
11:25:13,507::task::579::TaskManager.Task::(_updateState)
Task=`8518162d-eb91-44aa-819a-354e05807cb9`::moving from state
init -> state preparing<br>
Thread-1249::<a class="moz-txt-link-freetext"
href="INFO::2013-10-30" target="_blank">INFO::2013-10-30</a>
11:25:13,507::logUtils::44::dispatcher::(wrapper) Run and protect:
getSpmStatus(spUUID='e3cb7694-47f7-4eac-9201-922e381a25dc',
options=None)<br>
Thread-1249::<a class="moz-txt-link-freetext"
href="INFO::2013-10-30" target="_blank">INFO::2013-10-30</a>
11:25:13,508::logUtils::47::dispatcher::(wrapper) Run and protect:
getSpmStatus, Return response: {'spm_st': {'spmId': 1,
'spmStatus': 'SPM', 'spmLver': 3}}<br>
Thread-1249::DEBUG::2013-10-30
11:25:13,508::task::1168::TaskManager.Task::(prepare)
Task=`8518162d-eb91-44aa-819a-354e05807cb9`::finished: {'spm_st':
{'spmId': 1, 'spmStatus': 'SPM', 'spmLver':
3}}<br>
Thread-1249::DEBUG::2013-10-30
11:25:13,508::task::579::TaskManager.Task::(_updateState)
Task=`8518162d-eb91-44aa-819a-354e05807cb9`::moving from state
preparing -> state finished<br>
Thread-1249::DEBUG::2013-10-30
11:25:13,508::resourceManager::939::ResourceManager.Owner::(releaseAll)
Owner.releaseAll requests {} resources {}<br>
Thread-1249::DEBUG::2013-10-30
11:25:13,508::resourceManager::976::ResourceManager.Owner::(cancelAll)
Owner.cancelAll requests {}<br>
Thread-1249::DEBUG::2013-10-30
11:25:13,508::task::974::TaskManager.Task::(_decref)
Task=`8518162d-eb91-44aa-819a-354e05807cb9`::ref 0 aborting False<br>
Thread-1250::DEBUG::2013-10-30
11:25:13,510::BindingXMLRPC::177::vds::(wrapper) client
[172.16.0.5]<br>
Thread-1250::DEBUG::2013-10-30
11:25:13,510::task::579::TaskManager.Task::(_updateState)
Task=`221b537a-2c1b-418f-93ff-bf77d4029097`::moving from state
init -> state preparing<br>
Thread-1250::<a class="moz-txt-link-freetext"
href="INFO::2013-10-30" target="_blank">INFO::2013-10-30</a>
11:25:13,511::logUtils::44::dispatcher::(wrapper) Run and protect:
getStoragePoolInfo(spUUID='e3cb7694-47f7-4eac-9201-922e381a25dc',
options=None)<br>
Thread-1250::DEBUG::2013-10-30
11:25:13,511::resourceManager::197::ResourceManager.Request::(__init__)
ResName=`Storage.e3cb7694-47f7-4eac-9201-922e381a25dc`ReqID=`42f323ef-aa03-49e6-893f-0e4ff0764b6b`::Request
was made in '/usr/share/vdsm/storage/hsm.py' line '2560' at
'getStoragePoolInfo'<br>
Thread-1250::DEBUG::2013-10-30
11:25:13,511::resourceManager::541::ResourceManager::(registerResource)
Trying to register resource
'Storage.e3cb7694-47f7-4eac-9201-922e381a25dc' for lock type
'shared'<br>
Thread-1250::DEBUG::2013-10-30
11:25:13,511::resourceManager::600::ResourceManager::(registerResource)
Resource 'Storage.e3cb7694-47f7-4eac-9201-922e381a25dc' is free.
Now locking as 'shared' (1 active user)<br>
Thread-1250::DEBUG::2013-10-30
11:25:13,511::resourceManager::237::ResourceManager.Request::(grant)
ResName=`Storage.e3cb7694-47f7-4eac-9201-922e381a25dc`ReqID=`42f323ef-aa03-49e6-893f-0e4ff0764b6b`::Granted
request<br>
Thread-1250::DEBUG::2013-10-30
11:25:13,512::task::811::TaskManager.Task::(resourceAcquired)
Task=`221b537a-2c1b-418f-93ff-bf77d4029097`::_resourcesAcquired:
Storage.e3cb7694-47f7-4eac-9201-922e381a25dc (shared)<br>
Thread-1250::DEBUG::2013-10-30
11:25:13,512::task::974::TaskManager.Task::(_decref)
Task=`221b537a-2c1b-418f-93ff-bf77d4029097`::ref 1 aborting False<br>
Thread-1250::<a class="moz-txt-link-freetext"
href="INFO::2013-10-30" target="_blank">INFO::2013-10-30</a>
11:25:13,517::logUtils::47::dispatcher::(wrapper) Run and protect:
getStoragePoolInfo, Return response: {'info': {'spm_id': 1,
'master_uuid': '21e3d67f-fdec-4f87-b09e-53af994a6f87',
'name':
'GlusterSD', 'version': '3', 'domains':
'21e3d67f-fdec-4f87-b09e-53af994a6f87:Active,8e56a914-3395-48ad-ab4c-c2ca7f9956b4:Active',
'pool_status': 'connected', 'isoprefix':
'/rhev/data-center/mnt/172.16.0.5:_home_iso2/8e56a914-3395-48ad-ab4c-c2ca7f9956b4/images/11111111-1111-1111-1111-111111111111',
'type': 'GLUSTERFS', 'master_ver': 1, 'lver': 3},
'dominfo':
{'21e3d67f-fdec-4f87-b09e-53af994a6f87': {'status':
'Active',
'diskfree': '239969632256', 'alerts': [], 'version':
3,
'disktotal': '492120440832'},
'8e56a914-3395-48ad-ab4c-c2ca7f9956b4': {'status':
'Active',
'diskfree': '201653747712', 'alerts': [], 'version':
0,
'disktotal': '246783410176'}}}<br>
Thread-1250::DEBUG::2013-10-30
11:25:13,517::task::1168::TaskManager.Task::(prepare)
Task=`221b537a-2c1b-418f-93ff-bf77d4029097`::finished: {'info':
{'spm_id': 1, 'master_uuid':
'21e3d67f-fdec-4f87-b09e-53af994a6f87', 'name':
'GlusterSD',
'version': '3', 'domains':
'21e3d67f-fdec-4f87-b09e-53af994a6f87:Active,8e56a914-3395-48ad-ab4c-c2ca7f9956b4:Active',
'pool_status': 'connected', 'isoprefix':
'/rhev/data-center/mnt/172.16.0.5:_home_iso2/8e56a914-3395-48ad-ab4c-c2ca7f9956b4/images/11111111-1111-1111-1111-111111111111',
'type': 'GLUSTERFS', 'master_ver': 1, 'lver': 3},
'dominfo':
{'21e3d67f-fdec-4f87-b09e-53af994a6f87': {'status':
'Active',
'diskfree': '239969632256', 'alerts': [], 'version':
3,
'disktotal': '492120440832'},
'8e56a914-3395-48ad-ab4c-c2ca7f9956b4': {'status':
'Active',
'diskfree': '201653747712', 'alerts': [], 'version':
0,
'disktotal': '246783410176'}}}<br>
Thread-1250::DEBUG::2013-10-30
11:25:13,517::task::579::TaskManager.Task::(_updateState)
Task=`221b537a-2c1b-418f-93ff-bf77d4029097`::moving from state
preparing -> state finished<br>
Thread-1250::DEBUG::2013-10-30
11:25:13,517::resourceManager::939::ResourceManager.Owner::(releaseAll)
Owner.releaseAll requests {} resources
{'Storage.e3cb7694-47f7-4eac-9201-922e381a25dc': < ResourceRef
'Storage.e3cb7694-47f7-4eac-9201-922e381a25dc', isValid: 'True'
obj: 'None'>}<br>
Thread-1250::DEBUG::2013-10-30
11:25:13,518::resourceManager::976::ResourceManager.Owner::(cancelAll)
Owner.cancelAll requests {}<br>
Thread-1250::DEBUG::2013-10-30
11:25:13,518::resourceManager::615::ResourceManager::(releaseResource)
Trying to release resource
'Storage.e3cb7694-47f7-4eac-9201-922e381a25dc'<br>
Thread-1250::DEBUG::2013-10-30
11:25:13,518::resourceManager::634::ResourceManager::(releaseResource)
Released resource 'Storage.e3cb7694-47f7-4eac-9201-922e381a25dc'
(0 active users)<br>
Thread-1250::DEBUG::2013-10-30
11:25:13,518::resourceManager::640::ResourceManager::(releaseResource)
Resource 'Storage.e3cb7694-47f7-4eac-9201-922e381a25dc' is free,
finding out if anyone is waiting for it.<br>
Thread-1250::DEBUG::2013-10-30
11:25:13,518::resourceManager::648::ResourceManager::(releaseResource)
No one is waiting for resource
'Storage.e3cb7694-47f7-4eac-9201-922e381a25dc', Clearing records.<br>
Thread-1250::DEBUG::2013-10-30
11:25:13,518::task::974::TaskManager.Task::(_decref)
Task=`221b537a-2c1b-418f-93ff-bf77d4029097`::ref 0 aborting False<br>
Thread-242::DEBUG::2013-10-30
11:25:15,046::fileSD::238::Storage.Misc.excCmd::(getReadDelay)
'/usr/bin/dd iflag=direct
if=/rhev/data-center/mnt/glusterSD/172.16.0.100:vms/21e3d67f-fdec-4f87-b09e-53af994a6f87/dom_md/metadata
bs=4096 count=1' (cwd None)<br>
Thread-242::DEBUG::2013-10-30
11:25:15,051::fileSD::238::Storage.Misc.excCmd::(getReadDelay)
SUCCESS: <err> = '0+1 records in\n0+1 records out\n497 bytes
(497 B) copied, 0.00032077 s, 1.5 MB/s\n'; <rc> = 0<br>
Thread-243::DEBUG::2013-10-30
11:25:17,777::fileSD::238::Storage.Misc.excCmd::(getReadDelay)
'/usr/bin/dd iflag=direct
if=/rhev/data-center/mnt/172.16.0.5:_home_iso2/8e56a914-3395-48ad-ab4c-c2ca7f9956b4/dom_md/metadata
bs=4096 count=1' (cwd None)<br>
Thread-243::DEBUG::2013-10-30
11:25:17,780::fileSD::238::Storage.Misc.excCmd::(getReadDelay)
SUCCESS: <err> = '0+1 records in\n0+1 records out\n373 bytes
(373 B) copied, 9.9232e-05 s, 3.8 Thread-1239::DEBUG::2013-10-30
11:25:03,420::task::974::TaskManager.Task::(_decref)
Task=`d891f3d3-070d-403f-9050-f10651a7fc47`::ref 0 aborting False<br>
Thread-242::DEBUG::2013-10-30
11:25:04,982::domainMonitor::178::Storage.DomainMonitorThread::(_monitorDomain)
Refreshing domain 21e3d67f-fdec-4f87-b09e-53af994a6f87<br>
Thread-242::DEBUG::2013-10-30
11:25:04,992::fileSD::153::Storage.StorageDomain::(__init__)
Reading domain in path
/rhev/data-center/mnt/glusterSD/172.16.0.100:vms/21e3d67f-fdec-4f87-b09e-53af994a6f87<br>
Thread-242::DEBUG::2013-10-30
11:25:04,994::persistentDict::192::Storage.PersistentDict::(__init__)
Created a persistent dict with FileMetadataRW backend<br>
Thread-242::DEBUG::2013-10-30
11:25:05,005::persistentDict::234::Storage.PersistentDict::(refresh)
read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=vms',
'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60',
'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5',
'MASTER_VERSION=1',
'POOL_DESCRIPTION=GlusterSD',
'POOL_DOMAINS=21e3d67f-fdec-4f87-b09e-53af994a6f87:Active,8e56a914-3395-48ad-ab4c-c2ca7f9956b4:Active',
'POOL_SPM_ID=1', 'POOL_SPM_LVER=3',
'POOL_UUID=e3cb7694-47f7-4eac-9201-922e381a25dc',
'REMOTE_PATH=172.16.0.100:vms', 'ROLE=Master',
'SDUUID=21e3d67f-fdec-4f87-b09e-53af994a6f87', 'TYPE=GLUSTERFS',
'VERSION=3',
'_SHA_CKSUM=2d0dc3836063d45dd1d8046aaf00bce05c2455ea']<br>
Thread-242::DEBUG::2013-10-30
11:25:05,008::fileSD::535::Storage.StorageDomain::(imageGarbageCollector)
Removing remnants of deleted images []<br>
Thread-242::<a class="moz-txt-link-freetext"
href="INFO::2013-10-30" target="_blank">INFO::2013-10-30</a>
11:25:05,008::sd::374::Storage.StorageDomain::(_registerResourceNamespaces)
Resource namespace 21e3d67f-fdec-4f87-b09e-53af994a6f87_imageNS
already registered<br>
Thread-242::<a class="moz-txt-link-freetext"
href="INFO::2013-10-30" target="_blank">INFO::2013-10-30</a>
11:25:05,008::sd::382::Storage.StorageDomain::(_registerResourceNamespaces)
Resource namespace 21e3d67f-fdec-4f87-b09e-53af994a6f87_volumeNS
already registered<br>
Thread-242::DEBUG::2013-10-30
11:25:05,020::fileSD::238::Storage.Misc.excCmd::(getReadDelay)
'/usr/bin/dd iflag=direct
if=/rhev/data-center/mnt/glusterSD/172.16.0.100:vms/21e3d67f-fdec-4f87-b09e-53af994a6f87/dom_md/metadata
bs=4096 count=1' (cwd None)<br>
Thread-242::DEBUG::2013-10-30
11:25:05,026::fileSD::238::Storage.Misc.excCmd::(getReadDelay)
SUCCESS: <err> = '0+1 records in\n0+1 records out\n497 bytes
(497 B) copied, 0.000280701 s, 1.8 MB/s\n'; <rc> = 0<br>
Thread-243::DEBUG::2013-10-30
11:25:07,721::domainMonitor::178::Storage.DomainMonitorThread::(_monitorDomain)
Refreshing domain 8e56a914-3395-48ad-ab4c-c2ca7f9956b4<br>
Thread-243::DEBUG::2013-10-30
11:25:07,730::fileSD::153::Storage.StorageDomain::(__init__)
Reading domain in path
/rhev/data-center/mnt/172.16.0.5:_home_iso2/8e56a914-3395-48ad-ab4c-c2ca7f9956b4<br>
Thread-243::DEBUG::2013-10-30
11:25:07,731::persistentDict::192::Storage.PersistentDict::(__init__)
Created a persistent dict with FileMetadataRW backend<br>
Thread-243::DEBUG::2013-10-30
11:25:07,740::persistentDict::234::Storage.PersistentDict::(refresh)
read lines (FileMetadataRW)=['CLASS=Iso', 'DESCRIPTION=ISO',
'IOOPTIMEOUTSEC=1', 'LEASERETRIES=3', 'LEASETIMESEC=5',
'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5',
'MASTER_VERSION=0',
'POOL_UUID=01b79582-75e3-436d-bade-db653207620b,e3cb7694-47f7-4eac-9201-922e381a25dc',
'REMOTE_PATH=172.16.0.5:/home/iso2', 'ROLE=Regular',
'SDUUID=8e56a914-3395-48ad-ab4c-c2ca7f9956b4', 'TYPE=NFS',
'VERSION=0',
'_SHA_CKSUM=b0d102325f279bb8efa68c594cbace0b11c66783']<br>
Thread-243::DEBUG::2013-10-30
11:25:07,741::fileSD::535::Storage.StorageDomain::(imageGarbageCollector)
Removing remnants of deleted images []<br>
Thread-243::<a class="moz-txt-link-freetext"
href="INFO::2013-10-30" target="_blank">INFO::2013-10-30</a>
11:25:07,741::sd::374::Storage.StorageDomain::(_registerResourceNamespaces)
Resource namespace 8e56a914-3395-48ad-ab4c-c2ca7f9956b4_imageNS
already registered<br>
Thread-243::<a class="moz-txt-link-freetext"
href="INFO::2013-10-30" target="_blank">INFO::2013-10-30</a>
11:25:07,741::sd::382::Storage.StorageDomain::(_registerResourceNamespaces)
Resource namespace 8e56a914-3395-48ad-ab4c-c2ca7f9956b4_volumeNS
already registered<br>
Thread-243::DEBUG::2013-10-30
11:25:07,757::fileSD::238::Storage.Misc.excCmd::(getReadDelay)
'/usr/bin/dd iflag=direct
if=/rhev/data-center/mnt/172.16.0.5:_home_iso2/8e56a914-3395-48ad-ab4c-c2ca7f9956b4/dom_md/metadata
bs=4096 count=1' (cwd None)<br>
Thread-243::DEBUG::2013-10-30
11:25:07,760::fileSD::238::Storage.Misc.excCmd::(getReadDelay)
SUCCESS: <err> = '0+1 records in\n0+1 records out\n373 bytes
(373 B) copied, 0.000128829 s, 2.9 MB/s\n'; <rc> = 0<br>
Thread-1246::DEBUG::2013-10-30
11:25:09,944::task::579::TaskManager.Task::(_updateState)
Task=`c064522b-6fe7-4cb2-b85d-ad1f8185919a`::moving from state
init -> state preparing<br>
Thread-1246::<a class="moz-txt-link-freetext"
href="INFO::2013-10-30" target="_blank">INFO::2013-10-30</a>
11:25:09,944::logUtils::44::dispatcher::(wrapper) Run and protect:
repoStats(options=None)<br>
Thread-1246::<a class="moz-txt-link-freetext"
href="INFO::2013-10-30" target="_blank">INFO::2013-10-30</a>
11:25:09,945::logUtils::47::dispatcher::(wrapper) Run and protect:
repoStats, Return response:
{'21e3d67f-fdec-4f87-b09e-53af994a6f87': {'delay':
'0.000280701',
'lastCheck': '4.9', 'code': 0, 'valid': True,
'version': 3},
'8e56a914-3395-48ad-ab4c-c2ca7f9956b4': {'delay':
'0.000128829',
'lastCheck': '2.2', 'code': 0, 'valid': True,
'version': 0}}<br>
Thread-1246::DEBUG::2013-10-30
11:25:09,945::task::1168::TaskManager.Task::(prepare)
Task=`c064522b-6fe7-4cb2-b85d-ad1f8185919a`::finished:
{'21e3d67f-fdec-4f87-b09e-53af994a6f87': {'delay':
'0.000280701',
'lastCheck': '4.9', 'code': 0, 'valid': True,
'version': 3},
'8e56a914-3395-48ad-ab4c-c2ca7f9956b4': {'delay':
'0.000128829',
'lastCheck': '2.2', 'code': 0, 'valid': True,
'version': 0}}<br>
Thread-1246::DEBUG::2013-10-30
11:25:09,945::task::579::TaskManager.Task::(_updateState)
Task=`c064522b-6fe7-4cb2-b85d-ad1f8185919a`::moving from state
preparing -> state finished<br>
Thread-1246::DEBUG::2013-10-30
11:25:09,945::resourceManager::939::ResourceManager.Owner::(releaseAll)
Owner.releaseAll requests {} resources {}<br>
Thread-1246::DEBUG::2013-10-30
11:25:09,945::resourceManager::976::ResourceManager.Owner::(cancelAll)
Owner.cancelAll requests {}<br>
Thread-1246::DEBUG::2013-10-30
11:25:09,945::task::974::TaskManager.Task::(_decref)
Task=`c064522b-6fe7-4cb2-b85d-ad1f8185919a`::ref 0 aborting False<br>
Thread-1249::DEBUG::2013-10-30
11:25:13,507::BindingXMLRPC::177::vds::(wrapper) client
[172.16.0.5]<br>
Thread-1249::DEBUG::2013-10-30
11:25:13,507::task::579::TaskManager.Task::(_updateState)
Task=`8518162d-eb91-44aa-819a-354e05807cb9`::moving from state
init -> state preparing<br>
Thread-1249::<a class="moz-txt-link-freetext"
href="INFO::2013-10-30" target="_blank">INFO::2013-10-30</a>
11:25:13,507::logUtils::44::dispatcher::(wrapper) Run and protect:
getSpmStatus(spUUID='e3cb7694-47f7-4eac-9201-922e381a25dc',
options=None)<br>
Thread-1249::<a class="moz-txt-link-freetext"
href="INFO::2013-10-30" target="_blank">INFO::2013-10-30</a>
11:25:13,508::logUtils::47::dispatcher::(wrapper) Run and protect:
getSpmStatus, Return response: {'spm_st': {'spmId': 1,
'spmStatus': 'SPM', 'spmLver': 3}}<br>
Thread-1249::DEBUG::2013-10-30
11:25:13,508::task::1168::TaskManager.Task::(prepare)
Task=`8518162d-eb91-44aa-819a-354e05807cb9`::finished: {'spm_st':
{'spmId': 1, 'spmStatus': 'SPM', 'spmLver':
3}}<br>
Thread-1249::DEBUG::2013-10-30
11:25:13,508::task::579::TaskManager.Task::(_updateState)
Task=`8518162d-eb91-44aa-819a-354e05807cb9`::moving from state
preparing -> state finished<br>
Thread-1249::DEBUG::2013-10-30
11:25:13,508::resourceManager::939::ResourceManager.Owner::(releaseAll)
Owner.releaseAll requests {} resources {}<br>
Thread-1249::DEBUG::2013-10-30
11:25:13,508::resourceManager::976::ResourceManager.Owner::(cancelAll)
Owner.cancelAll requests {}<br>
Thread-1249::DEBUG::2013-10-30
11:25:13,508::task::974::TaskManager.Task::(_decref)
Task=`8518162d-eb91-44aa-819a-354e05807cb9`::ref 0 aborting False<br>
Thread-1250::DEBUG::2013-10-30
11:25:13,510::BindingXMLRPC::177::vds::(wrapper) client
[172.16.0.5]<br>
Thread-1250::DEBUG::2013-10-30
11:25:13,510::task::579::TaskManager.Task::(_updateState)
Task=`221b537a-2c1b-418f-93ff-bf77d4029097`::moving from state
init -> state preparing<br>
Thread-1250::<a class="moz-txt-link-freetext"
href="INFO::2013-10-30" target="_blank">INFO::2013-10-30</a>
11:25:13,511::logUtils::44::dispatcher::(wrapper) Run and protect:
getStoragePoolInfo(spUUID='e3cb7694-47f7-4eac-9201-922e381a25dc',
options=None)<br>
Thread-1250::DEBUG::2013-10-30
11:25:13,511::resourceManager::197::ResourceManager.Request::(__init__)
ResName=`Storage.e3cb7694-47f7-4eac-9201-922e381a25dc`ReqID=`42f323ef-aa03-49e6-893f-0e4ff0764b6b`::Request
was made in '/usr/share/vdsm/storage/hsm.py' line '2560' at
'getStoragePoolInfo'<br>
Thread-1250::DEBUG::2013-10-30
11:25:13,511::resourceManager::541::ResourceManager::(registerResource)
Trying to register resource
'Storage.e3cb7694-47f7-4eac-9201-922e381a25dc' for lock type
'shared'<br>
Thread-1250::DEBUG::2013-10-30
11:25:13,511::resourceManager::600::ResourceManager::(registerResource)
Resource 'Storage.e3cb7694-47f7-4eac-9201-922e381a25dc' is free.
Now locking as 'shared' (1 active user)<br>
Thread-1250::DEBUG::2013-10-30
11:25:13,511::resourceManager::237::ResourceManager.Request::(grant)
ResName=`Storage.e3cb7694-47f7-4eac-9201-922e381a25dc`ReqID=`42f323ef-aa03-49e6-893f-0e4ff0764b6b`::Granted
request<br>
Thread-1250::DEBUG::2013-10-30
11:25:13,512::task::811::TaskManager.Task::(resourceAcquired)
Task=`221b537a-2c1b-418f-93ff-bf77d4029097`::_resourcesAcquired:
Storage.e3cb7694-47f7-4eac-9201-922e381a25dc (shared)<br>
Thread-1250::DEBUG::2013-10-30
11:25:13,512::task::974::TaskManager.Task::(_decref)
Task=`221b537a-2c1b-418f-93ff-bf77d4029097`::ref 1 aborting False<br>
Thread-1250::<a class="moz-txt-link-freetext"
href="INFO::2013-10-30" target="_blank">INFO::2013-10-30</a>
11:25:13,517::logUtils::47::dispatcher::(wrapper) Run and protect:
getStoragePoolInfo, Return response: {'info': {'spm_id': 1,
'master_uuid': '21e3d67f-fdec-4f87-b09e-53af994a6f87',
'name':
'GlusterSD', 'version': '3', 'domains':
'21e3d67f-fdec-4f87-b09e-53af994a6f87:Active,8e56a914-3395-48ad-ab4c-c2ca7f9956b4:Active',
'pool_status': 'connected', 'isoprefix':
'/rhev/data-center/mnt/172.16.0.5:_home_iso2/8e56a914-3395-48ad-ab4c-c2ca7f9956b4/images/11111111-1111-1111-1111-111111111111',
'type': 'GLUSTERFS', 'master_ver': 1, 'lver': 3},
'dominfo':
{'21e3d67f-fdec-4f87-b09e-53af994a6f87': {'status':
'Active',
'diskfree': '239969632256', 'alerts': [], 'version':
3,
'disktotal': '492120440832'},
'8e56a914-3395-48ad-ab4c-c2ca7f9956b4': {'status':
'Active',
'diskfree': '201653747712', 'alerts': [], 'version':
0,
'disktotal': '246783410176'}}}<br>
Thread-1250::DEBUG::2013-10-30
11:25:13,517::task::1168::TaskManager.Task::(prepare)
Task=`221b537a-2c1b-418f-93ff-bf77d4029097`::finished: {'info':
{'spm_id': 1, 'master_uuid':
'21e3d67f-fdec-4f87-b09e-53af994a6f87', 'name':
'GlusterSD',
'version': '3', 'domains':
'21e3d67f-fdec-4f87-b09e-53af994a6f87:Active,8e56a914-3395-48ad-ab4c-c2ca7f9956b4:Active',
'pool_status': 'connected', 'isoprefix':
'/rhev/data-center/mnt/172.16.0.5:_home_iso2/8e56a914-3395-48ad-ab4c-c2ca7f9956b4/images/11111111-1111-1111-1111-111111111111',
'type': 'GLUSTERFS', 'master_ver': 1, 'lver': 3},
'dominfo':
{'21e3d67f-fdec-4f87-b09e-53af994a6f87': {'status':
'Active',
'diskfree': '239969632256', 'alerts': [], 'version':
3,
'disktotal': '492120440832'},
'8e56a914-3395-48ad-ab4c-c2ca7f9956b4': {'status':
'Active',
'diskfree': '201653747712', 'alerts': [], 'version':
0,
'disktotal': '246783410176'}}}<br>
Thread-1250::DEBUG::2013-10-30
11:25:13,517::task::579::TaskManager.Task::(_updateState)
Task=`221b537a-2c1b-418f-93ff-bf77d4029097`::moving from state
preparing -> state finished<br>
Thread-1250::DEBUG::2013-10-30
11:25:13,517::resourceManager::939::ResourceManager.Owner::(releaseAll)
Owner.releaseAll requests {} resources
{'Storage.e3cb7694-47f7-4eac-9201-922e381a25dc': < ResourceRef
'Storage.e3cb7694-47f7-4eac-9201-922e381a25dc', isValid: 'True'
obj: 'None'>}<br>
Thread-1250::DEBUG::2013-10-30
11:25:13,518::resourceManager::976::ResourceManager.Owner::(cancelAll)
Owner.cancelAll requests {}<br>
Thread-1250::DEBUG::2013-10-30
11:25:13,518::resourceManager::615::ResourceManager::(releaseResource)
Trying to release resource
'Storage.e3cb7694-47f7-4eac-9201-922e381a25dc'<br>
Thread-1250::DEBUG::2013-10-30
11:25:13,518::resourceManager::634::ResourceManager::(releaseResource)
Released resource 'Storage.e3cb7694-47f7-4eac-9201-922e381a25dc'
(0 active users)<br>
Thread-1250::DEBUG::2013-10-30
11:25:13,518::resourceManager::640::ResourceManager::(releaseResource)
Resource 'Storage.e3cb7694-47f7-4eac-9201-922e381a25dc' is free,
finding out if anyone is waiting for it.<br>
Thread-1250::DEBUG::2013-10-30
11:25:13,518::resourceManager::648::ResourceManager::(releaseResource)
No one is waiting for resource
'Storage.e3cb7694-47f7-4eac-9201-922e381a25dc', Clearing records.<br>
Thread-1250::DEBUG::2013-10-30
11:25:13,518::task::974::TaskManager.Task::(_decref)
Task=`221b537a-2c1b-418f-93ff-bf77d4029097`::ref 0 aborting False<br>
Thread-242::DEBUG::2013-10-30
11:25:15,046::fileSD::238::Storage.Misc.excCmd::(getReadDelay)
'/usr/bin/dd iflag=direct
if=/rhev/data-center/mnt/glusterSD/172.16.0.100:vms/21e3d67f-fdec-4f87-b09e-53af994a6f87/dom_md/metadata
bs=4096 count=1' (cwd None)<br>
Thread-242::DEBUG::2013-10-30
11:25:15,051::fileSD::238::Storage.Misc.excCmd::(getReadDelay)
SUCCESS: <err> = '0+1 records in\n0+1 records out\n497 bytes
(497 B) copied, 0.00032077 s, 1.5 MB/s\n'; <rc> = 0<br>
Thread-243::DEBUG::2013-10-30
11:25:17,777::fileSD::238::Storage.Misc.excCmd::(getReadDelay)
'/usr/bin/dd iflag=direct
if=/rhev/data-center/mnt/172.16.0.5:_home_iso2/8e56a914-3395-48ad-ab4c-c2ca7f9956b4/dom_md/metadata
bs=4096 count=1' (cwd None)<br>
Thread-243::DEBUG::2013-10-30
11:25:17,780::fileSD::238::Storage.Misc.excCmd::(getReadDelay)
SUCCESS: <err> = '0+1 records in\n0+1 records out\n373 bytes
(373 B) copied, 9.9232e-05 s, 3.8 MB/s\n'; <rc> =
0<br><br><br>
engine.log<br><br>
2013-10-30 11:17:47,729 INFO
[org.ovirt.engine.core.bll.RunVmOnceCommand]
(ajp--127.0.0.1-8702-6) Running command: RunVmOnceCommand
internal: false. Entities affected : ID:
200dfb05-461e-49d9-95a2-c0a7c7ced669 Type: VM<br>
2013-10-30 11:17:47,743 INFO
[org.ovirt.engine.core.vdsbroker.CreateVmVDSCommand]
(ajp--127.0.0.1-8702-6) START, CreateVmVDSCommand(HostName =
Hypervisor, HostId = da764821-0650-40f0-b7cf-038766fbd2ca,
vmId=200dfb05-461e-49d9-95a2-c0a7c7ced669, vm=VM [CentOS_30]), log
id: 638a3a0e<br>
2013-10-30 11:17:47,765 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand]
(ajp--127.0.0.1-8702-6) START, CreateVDSCommand(HostName =
Hypervisor, HostId = da764821-0650-40f0-b7cf-038766fbd2ca,
vmId=200dfb05-461e-49d9-95a2-c0a7c7ced669, vm=VM [CentOS_30]), log
id: 297dbca2<br>
2013-10-30 11:17:47,784 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand]
(ajp--127.0.0.1-8702-6)
org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand
spiceSslCipherSuite=DEFAULT,memSize=2048,kvmEnable=true,smp=1,vmType=kvm,emulatedMachine=pc-1.0,keyboardLayout=en-us,memGuaranteedSize=1365,pitReinjection=false,nice=0,display=qxl,smartcardEnable=false,smpCoresPerSocket=1,spiceSecureChannels=smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard,timeOffset=0,transparentHugePages=true,vmId=200dfb05-461e-49d9-95a2-c0a7c7ced669,devices=[Ljava.util.HashMap;@f3eee3e,acpiEnable=true,vmName=CentOS_30,cpuType=Westmere,custom={}<br>
2013-10-30 11:17:47,785 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand]
(ajp--127.0.0.1-8702-6) FINISH, CreateVDSCommand, log id: 297dbca2<br>
2013-10-30 11:17:47,786 INFO
[org.ovirt.engine.core.vdsbroker.CreateVmVDSCommand]
(ajp--127.0.0.1-8702-6) FINISH, CreateVmVDSCommand, return:
WaitForLaunch, log id: 638a3a0e<br>
2013-10-30 11:17:47,812 INFO
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(ajp--127.0.0.1-8702-6) Correlation ID: 4f8bc4f9, Job ID:
74a77fc0-7e83-44c0-b3d7-334eb38612b4, Call Stack: null, Custom
Event ID: -1, Message: VM CentOS_30 was started by admin@internal
(Host: Hypervisor).<br>
2013-10-30 11:17:51,115 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.FullListVdsCommand]
(DefaultQuartzScheduler_Worker-37) START,
FullListVdsCommand(HostName = Hypervisor, HostId =
da764821-0650-40f0-b7cf-038766fbd2ca, vds=Host[Hypervisor],
vmIds=[200dfb05-461e-49d9-95a2-c0a7c7ced669]), log id: 546bd3e2<br>
2013-10-30 11:17:51,119 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.FullListVdsCommand]
(DefaultQuartzScheduler_Worker-37) FINISH, FullListVdsCommand,
return: [Ljava.util.HashMap;@318a7164, log id: 546bd3e2<br>
2013-10-30 11:17:51,121 INFO
[org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo]
(DefaultQuartzScheduler_Worker-37) Received a scsi Device without
an address when processing VM 200dfb05-461e-49d9-95a2-c0a7c7ced669
devices, skipping device: {model=virtio-scsi, device=scsi,
type=controller}<br>
2013-10-30 11:17:51,121 INFO
[org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo]
(DefaultQuartzScheduler_Worker-37) Received a cdrom Device without
an address when processing VM 200dfb05-461e-49d9-95a2-c0a7c7ced669
devices, skipping device: {shared=false, bootOrder=1, iface=ide,
index=2, specParams={}, device=cdrom,
path=/rhev/data-center/mnt/172.16.0.5:_home_iso2/8e56a914-3395-48ad-ab4c-c2ca7f9956b4/images/11111111-1111-1111-1111-111111111111/CentOS-6.4-x86_64-bin-DVD1.iso,
type=disk, readonly=true,
deviceId=e29c7ac7-f872-43e3-90e2-cb2205c0203f}<br>
2013-10-30 11:17:51,122 INFO
[org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo]
(DefaultQuartzScheduler_Worker-37) Received a disk Device without
an address when processing VM 200dfb05-461e-49d9-95a2-c0a7c7ced669
devices, skipping device: {shared=false,
volumeID=202adc86-7857-40eb-8ca6-7cec3ef0d2d6, index=0,
propagateErrors=off, format=raw, type=disk, truesize=4096,
reqsize=0, bootOrder=2, iface=virtio,
volumeChain=[Ljava.lang.Object;@8741843,
imageID=b73a79fe-401b-434c-b023-6de4c3eb100d,
domainID=21e3d67f-fdec-4f87-b09e-53af994a6f87, specParams={},
optional=false, volumeInfo={volfileServer=172.16.0.100, volPort=0,
protocol=gluster, volTransport=tcp,
path=vms/21e3d67f-fdec-4f87-b09e-53af994a6f87/images/b73a79fe-401b-434c-b023-6de4c3eb100d/202adc86-7857-40eb-8ca6-7cec3ef0d2d6,
volType=network},
path=/rhev/data-center/e3cb7694-47f7-4eac-9201-922e381a25dc/21e3d67f-fdec-4f87-b09e-53af994a6f87/images/b73a79fe-401b-434c-b023-6de4c3eb100d/202adc86-7857-40eb-8ca6-7cec3ef0d2d6,
device=disk, poolID=e3cb7694-47f7-4eac-9201-922e381a25dc,
readonly=false, deviceId=b73a79fe-401b-434c-b023-6de4c3eb100d,
apparentsize=32212254720}<br>
2013-10-30 11:17:51,123 INFO
[org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo]
(DefaultQuartzScheduler_Worker-37) Received a memballoon Device
without an address when processing VM
200dfb05-461e-49d9-95a2-c0a7c7ced669 devices, skipping device:
{specParams={model=virtio}, target=2097152, device=memballoon,
type=balloon,
deviceId=b61b058d-cdfe-4d7c-8e6c-1bfd631cb26c}<br><br></div><br>_______________________________________________<br>Users
mailing
list<br>Users@ovirt.org<br>http://lists.ovirt.org/mailman/listinfo/users<br></blockquote><div><br></div></div></body></html>
------=_Part_14812387_1517716221.1383129966977--
3:58 p.m.
On Wed, Oct 30, 2013 at 11:34:21AM +0100, Alessandro Bianchi wrote:
Hi everyone
I've set up a gluster storage with two replicated bricks
DC is up and I created a VM to test gluster storage
If I start the VM WITHOUT any disk attached (only one virtual DVD) it
starts fine.
If I attach a gluster domain disk thin provisioning 30 Gb the Vm stucks in
"waiting for launch" state
I see no special activity on the gluster servers (they serve several other
shares with no troubles at all and even the ISO domain is a NFS on
locally mounted gluster and works fine)
I've double checked all the pre requisites and they look fine (F 19 -
gluster setup insecure in both glusterd.vol and volume options -
uid/gid/insecure )
Am I doing something wrong?
I'm even unable to stop the VM from the engine GUI
Any advise?
Which version of ovirt are you using? Hopefully ovirt-3.3.0.1.
For how long is the VM stuck in its "wait for launch" state?
What does `virsh -r list` has to say while startup stalls?
Would you provide more content of your vdsm.log and possibly
libvirtd.log so we can understand what blocks the VM start-up? Please
use attachement of pastebin, as your mail agents wreaks havoc to the log
lines.
8:04 p.m.
On Wed, Oct 30, 2013 at 02:40:02PM +0100, Alessandro Bianchi wrote:
Il 30/10/2013 13:58, Dan Kenigsberg ha scritto:
On Wed, Oct 30, 2013 at 11:34:21AM +0100, Alessandro Bianchi wrote:
Hi everyone
I've set up a gluster storage with two replicated bricks
DC is up and I created a VM to test gluster storage
If I start the VM WITHOUT any disk attached (only one virtual DVD) it
starts fine.
If I attach a gluster domain disk thin provisioning 30 Gb the Vm stucks in
"waiting for launch" state
I see no special activity on the gluster servers (they serve several other
shares with no troubles at all and even the ISO domain is a NFS on
locally mounted gluster and works fine)
I've double checked all the pre requisites and they look fine (F 19 -
gluster setup insecure in both glusterd.vol and volume options -
uid/gid/insecure )
Am I doing something wrong?
I'm even unable to stop the VM from the engine GUI
Any advise?
Which version of ovirt are you using? Hopefully ovirt-3.3.0.1.
For how long is the VM stuck in its "wait for launch" state?
What does `virsh -r list` has to say while startup stalls?
Would you provide more content of your vdsm.log and possibly
libvirtd.log so we can understand what blocks the VM start-up? Please
use attachement of pastebin, as your mail agents wreaks havoc to the log
lines.
Thank you for your answer.
Here are the "facts"
In the GUI I see
"waiting for launch 3 h"
virsh -r list
Id Nome Stato
----------------------------------------------------
3 CentOS_30 terminato
vdsClient -s 0 list table
200dfb05-461e-49d9-95a2-c0a7c7ced669 0 CentOS_30
WaitForLaunch
Packages:
ovirt-engine-userportal-3.3.0.1-1.fc19.noarch
ovirt-log-collector-3.3.1-1.fc19.noarch
ovirt-engine-restapi-3.3.0.1-1.fc19.noarch
ovirt-engine-setup-3.3.0.1-1.fc19.noarch
ovirt-engine-backend-3.3.0.1-1.fc19.noarch
ovirt-host-deploy-java-1.1.1-1.fc19.noarch
ovirt-release-fedora-8-1.noarch
ovirt-engine-setup-plugin-allinone-3.3.0.1-1.fc19.noarch
ovirt-engine-webadmin-portal-3.3.0.1-1.fc19.noarch
ovirt-engine-sdk-python-3.3.0.7-1.fc19.noarch
ovirt-iso-uploader-3.3.1-1.fc19.noarch
ovirt-engine-websocket-proxy-3.3.0.1-1.fc19.noarch
ovirt-engine-dbscripts-3.3.0.1-1.fc19.noarch
ovirt-host-deploy-offline-1.1.1-1.fc19.noarch
ovirt-engine-cli-3.3.0.5-1.fc19.noarch
ovirt-engine-tools-3.3.0.1-1.fc19.noarch
ovirt-engine-lib-3.3.0.1-1.fc19.noarch
ovirt-image-uploader-3.3.1-1.fc19.noarch
ovirt-engine-3.3.0.1-1.fc19.noarch
ovirt-host-deploy-1.1.1-1.fc19.noarch
I attach the full vdsm log
Look around 30-10 10:30 to see all what happens
Despite the "terminated" label in output from virsh I still see the VM
"waiting for launch" in the GUI, so I suspect the answer to "how
long" may
be "forever"
Since this is a test VM I can do whatever test you may need to track the
problem included destroy and rebuild
It would be great to have gluster support stable in ovirt!
Thank you for your efforts
The log has an ominous failed attempt to start the VM, followed by an
immediate vdsm crash. Is it reproducible?
We have plenty of issues lurking here:
1. Why has libvirt failed to create the VM? For this, please find clues
in the complete non-line-broken CentOS_30.log and libvirtd.log.
2. Why was vdsm killed? Does /var/log/message has a clue from systemd?
3. We may have a nasty race: if Vdsm crashes just before it has
registered that the VM is down.
4. We used to force Vdsm to run with LC_ALL=C. It seems that the grand
service rewrite by Zhou (http://gerrit.ovirt.org/15578) has changed
that. This may have adverse effects, since AFAIR we sometimes parse
application output, and assume that it's in C. Having a non-English
log file is problematic on it's own for support personal, used to
grep for keywords. ybronhei, was it intensional? Can it be reverted
or at least scrutinized?
Thread-77::ERROR::2013-10-30 08:51:13,147::vm::2062::vm.Vm::(_startUnderlyingVm)
vmId=`73e6615b-78c3-42e5-803a-3fc20d64ca32`::The vm start process failed
Traceback (most recent call last):
File "/usr/share/vdsm/vm.py", line 2022, in _startUnderlyingVm
self._run()
File "/usr/share/vdsm/vm.py", line 2906, in _run
self._connection.createXML(domxml, flags),
File "/usr/lib64/python2.7/site-packages/vdsm/libvirtconnection.py", line 76,
in wrapper
ret = f(*args, **kwargs)
File "/usr/lib64/python2.7/site-packages/libvirt.py", line 2805, in createXML
if ret is None:raise libvirtError('virDomainCreateXML() failed', conn=self)
libvirtError: Unable to read from monitor: Connessione interrotta dal corrispondente
Thread-77::DEBUG::2013-10-30 08:51:13,151::vm::2448::vm.Vm::(setDownStatus)
vmId=`73e6615b-78c3-42e5-803a-3fc20d64ca32`::Changed state to Down: Unable to read from
monitor: Connessione interrotta dal corrispondente
MainThread::DEBUG::2013-10-30 08:51:13,153::vdsm::45::vds::(sigtermHandler) Received
signal 15
MainThread::DEBUG::2013-10-30 08:51:13,153::clientIF::210::vds::(prepareForShutdown)
cannot run prepareForShutdown twice
MainThread::DEBUG::2013-10-30 08:51:15,633::vdsm::45::vds::(sigtermHandler) Received
signal 15
MainThread::DEBUG::2013-10-30 08:51:15,633::clientIF::210::vds::(prepareForShutdown)
cannot run prepareForShutdown twice
MainThread::INFO::2013-10-30 08:51:15,700::vdsm::101::vds::(run) (PID: 7726) I am the
actual vdsm 4.12.1-4.fc19 hypervisor.skynet.it (3.11.1-200.fc19.x86_64)
10:41 p.m.
Il 30/10/2013 18:04, Dan Kenigsberg ha scritto:
On Wed, Oct 30, 2013 at 02:40:02PM +0100, Alessandro Bianchi wrote:
> Il 30/10/2013 13:58, Dan Kenigsberg ha scritto:
>
> On Wed, Oct 30, 2013 at 11:34:21AM +0100, Alessandro Bianchi wrote:
>
> Hi everyone
>
> I've set up a gluster storage with two replicated bricks
>
> DC is up and I created a VM to test gluster storage
>
> If I start the VM WITHOUT any disk attached (only one virtual DVD) it
> starts fine.
>
> If I attach a gluster domain disk thin provisioning 30 Gb the Vm stucks in
> "waiting for launch" state
>
> I see no special activity on the gluster servers (they serve several other
> shares with no troubles at all and even the ISO domain is a NFS on
> locally mounted gluster and works fine)
>
> I've double checked all the pre requisites and they look fine (F 19 -
> gluster setup insecure in both glusterd.vol and volume options -
> uid/gid/insecure )
>
> Am I doing something wrong?
>
> I'm even unable to stop the VM from the engine GUI
>
> Any advise?
>
> Which version of ovirt are you using? Hopefully ovirt-3.3.0.1.
> For how long is the VM stuck in its "wait for launch" state?
> What does `virsh -r list` has to say while startup stalls?
> Would you provide more content of your vdsm.log and possibly
> libvirtd.log so we can understand what blocks the VM start-up? Please
> use attachement of pastebin, as your mail agents wreaks havoc to the log
> lines.
>
>
> Thank you for your answer.
>
> Here are the "facts"
>
> In the GUI I see
>
> "waiting for launch 3 h"
>
> virsh -r list
> Id Nome Stato
> ----------------------------------------------------
> 3 CentOS_30 terminato
>
> vdsClient -s 0 list table
> 200dfb05-461e-49d9-95a2-c0a7c7ced669 0 CentOS_30
> WaitForLaunch
>
> Packages:
>
> ovirt-engine-userportal-3.3.0.1-1.fc19.noarch
> ovirt-log-collector-3.3.1-1.fc19.noarch
> ovirt-engine-restapi-3.3.0.1-1.fc19.noarch
> ovirt-engine-setup-3.3.0.1-1.fc19.noarch
> ovirt-engine-backend-3.3.0.1-1.fc19.noarch
> ovirt-host-deploy-java-1.1.1-1.fc19.noarch
> ovirt-release-fedora-8-1.noarch
> ovirt-engine-setup-plugin-allinone-3.3.0.1-1.fc19.noarch
> ovirt-engine-webadmin-portal-3.3.0.1-1.fc19.noarch
> ovirt-engine-sdk-python-3.3.0.7-1.fc19.noarch
> ovirt-iso-uploader-3.3.1-1.fc19.noarch
> ovirt-engine-websocket-proxy-3.3.0.1-1.fc19.noarch
> ovirt-engine-dbscripts-3.3.0.1-1.fc19.noarch
> ovirt-host-deploy-offline-1.1.1-1.fc19.noarch
> ovirt-engine-cli-3.3.0.5-1.fc19.noarch
> ovirt-engine-tools-3.3.0.1-1.fc19.noarch
> ovirt-engine-lib-3.3.0.1-1.fc19.noarch
> ovirt-image-uploader-3.3.1-1.fc19.noarch
> ovirt-engine-3.3.0.1-1.fc19.noarch
> ovirt-host-deploy-1.1.1-1.fc19.noarch
>
> I attach the full vdsm log
>
> Look around 30-10 10:30 to see all what happens
>
> Despite the "terminated" label in output from virsh I still see the VM
> "waiting for launch" in the GUI, so I suspect the answer to "how
long" may
> be "forever"
>
> Since this is a test VM I can do whatever test you may need to track the
> problem included destroy and rebuild
>
> It would be great to have gluster support stable in ovirt!
>
> Thank you for your efforts
The log has an ominous failed attempt to start the VM, followed by an
immediate vdsm crash. Is it reproducible?
We have plenty of issues lurking here:
1. Why has libvirt failed to create the VM? For this, please find clues
in the complete non-line-broken CentOS_30.log and libvirtd.log.
attached to
this messages
2. Why was vdsm killed? Does /var/log/message has a clue from systemd?
result of
cat /var/log/messages | grep vdsm attached
3. We may have a nasty race: if Vdsm crashes just before it has
registered that the VM is down.
4. We used to force Vdsm to run with LC_ALL=C. It seems that the grand
service rewrite by Zhou (http://gerrit.ovirt.org/15578) has changed
that. This may have adverse effects, since AFAIR we sometimes parse
application output, and assume that it's in C. Having a non-English
log file is problematic on it's own for support personal, used to
grep for keywords. ybronhei, was it intensional? Can it be reverted
or at least scrutinized?
currentely it still says "waiting for launch
9h"
I don't abort it so if you need any other info I can have them
Thgank you
Thread-77::ERROR::2013-10-30 08:51:13,147::vm::2062::vm.Vm::(_startUnderlyingVm)
vmId=`73e6615b-78c3-42e5-803a-3fc20d64ca32`::The vm start process failed
Traceback (most recent call last):
File "/usr/share/vdsm/vm.py", line 2022, in _startUnderlyingVm
self._run()
File "/usr/share/vdsm/vm.py", line 2906, in _run
self._connection.createXML(domxml, flags),
File "/usr/lib64/python2.7/site-packages/vdsm/libvirtconnection.py", line
76, in wrapper
ret = f(*args, **kwargs)
File "/usr/lib64/python2.7/site-packages/libvirt.py", line 2805, in
createXML
if ret is None:raise libvirtError('virDomainCreateXML() failed', conn=self)
libvirtError: Unable to read from monitor: Connessione interrotta dal corrispondente
Thread-77::DEBUG::2013-10-30 08:51:13,151::vm::2448::vm.Vm::(setDownStatus)
vmId=`73e6615b-78c3-42e5-803a-3fc20d64ca32`::Changed state to Down: Unable to read from
monitor: Connessione interrotta dal corrispondente
MainThread::DEBUG::2013-10-30 08:51:13,153::vdsm::45::vds::(sigtermHandler) Received
signal 15
MainThread::DEBUG::2013-10-30 08:51:13,153::clientIF::210::vds::(prepareForShutdown)
cannot run prepareForShutdown twice
MainThread::DEBUG::2013-10-30 08:51:15,633::vdsm::45::vds::(sigtermHandler) Received
signal 15
MainThread::DEBUG::2013-10-30 08:51:15,633::clientIF::210::vds::(prepareForShutdown)
cannot run prepareForShutdown twice
MainThread::INFO::2013-10-30 08:51:15,700::vdsm::101::vds::(run) (PID: 7726) I am the
actual vdsm 4.12.1-4.fc19 hypervisor.skynet.it (3.11.1-200.fc19.x86_64)
--
SkyNet SRL
Via Maggiate 67/a - 28021 Borgomanero (NO) - tel. +39 0322-836487/834765
- fax +39 0322-836608
http://www.skynet.it <http://www.skynet.it/>
Autorizzazione Ministeriale n.197
Le informazioni contenute in questo messaggio sono riservate e
confidenziali ed è vietata la diffusione in qualunque modo eseguita.
Qualora Lei non fosse la persona a cui il presente messaggio è
destinato, La invitiamo ad eliminarlo ed a distruggerlo non
divulgandolo, dandocene gentilmente comunicazione.
Per qualsiasi informazione si prega di contattare info(a)skynet.it (e-mail
dell'azienda). Rif. D.L. 196/2003
1:24 a.m.
On Wed, Oct 30, 2013 at 08:41:43PM +0100, Alessandro Bianchi wrote:
Il 30/10/2013 18:04, Dan Kenigsberg ha scritto:
>On Wed, Oct 30, 2013 at 02:40:02PM +0100, Alessandro Bianchi wrote:
>> Il 30/10/2013 13:58, Dan Kenigsberg ha scritto:
>>
>> On Wed, Oct 30, 2013 at 11:34:21AM +0100, Alessandro Bianchi wrote:
>>
>> Hi everyone
>>
>> I've set up a gluster storage with two replicated bricks
>>
>> DC is up and I created a VM to test gluster storage
>>
>> If I start the VM WITHOUT any disk attached (only one virtual DVD) it
>> starts fine.
>>
>> If I attach a gluster domain disk thin provisioning 30 Gb the Vm stucks in
>> "waiting for launch" state
>>
>> I see no special activity on the gluster servers (they serve several other
>> shares with no troubles at all and even the ISO domain is a NFS on
>> locally mounted gluster and works fine)
>>
>> I've double checked all the pre requisites and they look fine (F 19 -
>> gluster setup insecure in both glusterd.vol and volume options -
>> uid/gid/insecure )
>>
>> Am I doing something wrong?
>>
>> I'm even unable to stop the VM from the engine GUI
>>
>> Any advise?
>>
>> Which version of ovirt are you using? Hopefully ovirt-3.3.0.1.
>> For how long is the VM stuck in its "wait for launch" state?
>> What does `virsh -r list` has to say while startup stalls?
>> Would you provide more content of your vdsm.log and possibly
>> libvirtd.log so we can understand what blocks the VM start-up? Please
>> use attachement of pastebin, as your mail agents wreaks havoc to the log
>> lines.
>>
>>
>> Thank you for your answer.
>>
>> Here are the "facts"
>>
>> In the GUI I see
>>
>> "waiting for launch 3 h"
>>
>> virsh -r list
>> Id Nome Stato
>> ----------------------------------------------------
>> 3 CentOS_30 terminato
>>
>> vdsClient -s 0 list table
>> 200dfb05-461e-49d9-95a2-c0a7c7ced669 0 CentOS_30
>> WaitForLaunch
>>
>> Packages:
>>
>> ovirt-engine-userportal-3.3.0.1-1.fc19.noarch
>> ovirt-log-collector-3.3.1-1.fc19.noarch
>> ovirt-engine-restapi-3.3.0.1-1.fc19.noarch
>> ovirt-engine-setup-3.3.0.1-1.fc19.noarch
>> ovirt-engine-backend-3.3.0.1-1.fc19.noarch
>> ovirt-host-deploy-java-1.1.1-1.fc19.noarch
>> ovirt-release-fedora-8-1.noarch
>> ovirt-engine-setup-plugin-allinone-3.3.0.1-1.fc19.noarch
>> ovirt-engine-webadmin-portal-3.3.0.1-1.fc19.noarch
>> ovirt-engine-sdk-python-3.3.0.7-1.fc19.noarch
>> ovirt-iso-uploader-3.3.1-1.fc19.noarch
>> ovirt-engine-websocket-proxy-3.3.0.1-1.fc19.noarch
>> ovirt-engine-dbscripts-3.3.0.1-1.fc19.noarch
>> ovirt-host-deploy-offline-1.1.1-1.fc19.noarch
>> ovirt-engine-cli-3.3.0.5-1.fc19.noarch
>> ovirt-engine-tools-3.3.0.1-1.fc19.noarch
>> ovirt-engine-lib-3.3.0.1-1.fc19.noarch
>> ovirt-image-uploader-3.3.1-1.fc19.noarch
>> ovirt-engine-3.3.0.1-1.fc19.noarch
>> ovirt-host-deploy-1.1.1-1.fc19.noarch
>>
>> I attach the full vdsm log
>>
>> Look around 30-10 10:30 to see all what happens
>>
>> Despite the "terminated" label in output from virsh I still see the
VM
>> "waiting for launch" in the GUI, so I suspect the answer to
"how long" may
>> be "forever"
>>
>> Since this is a test VM I can do whatever test you may need to track the
>> problem included destroy and rebuild
>>
>> It would be great to have gluster support stable in ovirt!
>>
>> Thank you for your efforts
>The log has an ominous failed attempt to start the VM, followed by an
>immediate vdsm crash. Is it reproducible?
>
>We have plenty of issues lurking here:
>1. Why has libvirt failed to create the VM? For this, please find clues
> in the complete non-line-broken CentOS_30.log and libvirtd.log.
attached to this messages
>
>2. Why was vdsm killed? Does /var/log/message has a clue from systemd?
result of cat /var/log/messages | grep vdsm attached
I do not see an explicit attempt to take vdsmd down. Do you see any other
incriminating message correlated with
Oct 30 08:51:15 hypervisor respawn: slave '/usr/share/vdsm/vdsm' died, respawning
slave
>
>3. We may have a nasty race: if Vdsm crashes just before it has
> registered that the VM is down.
Actually, this is not the issue: vdsm tries (and fails, due to qemu/libvirt
bug) to destroy the VM.
>
>4. We used to force Vdsm to run with LC_ALL=C. It seems that the grand
> service rewrite by Zhou (http://gerrit.ovirt.org/15578) has changed
> that. This may have adverse effects, since AFAIR we sometimes parse
> application output, and assume that it's in C. Having a non-English
> log file is problematic on it's own for support personal, used to
> grep for keywords. ybronhei, was it intensional? Can it be reverted
> or at least scrutinized?
currentely it still says "waiting for launch 9h"
I don't abort it so if you need any other info I can have them
libvirtd fails to connect to qemu's monitor. This smells like a qemu bug that
is beyond my over-the-mailing-list debugging abilities :-(
You may want to strace or gdb the running qemu process, or to try to re-attach
to it by restarting libvirtd.
2013-10-30 07:51:10.045+0000: 8304: debug : qemuProcessStart:3804 : Waiting for monitor to
show up
2013-10-30 07:51:10.045+0000: 8304: debug : qemuProcessWaitForMonitor:1707 : Connect
monitor to 0x7fc1640eab80 'CentOS_30'
2013-10-30 07:51:10.246+0000: 8304: debug : qemuMonitorOpenInternal:751 :
QEMU_MONITOR_NEW: mon=0x7fc1640ef6b0 refs=2 fd=27
2013-10-30 07:51:10.246+0000: 8304: debug : qemuMonitorSetCapabilities:1145 :
mon=0x7fc1640ef6b0
2013-10-30 07:51:10.246+0000: 8304: debug : qemuMonitorSend:887 : QEMU_MONITOR_SEND_MSG:
mon=0x7fc1640ef6b0
msg={"execute":"qmp_capabilities","id":"libvirt-1"}
fd=-1
2013-10-30 07:51:13.097+0000: 8296: error : qemuMonitorIORead:505 : Unable to read from
monitor: Connessione interrotta dal corrispondente
2013-10-30 07:51:13.097+0000: 8296: debug : qemuMonitorIO:638 : Error on monitor Unable to
read from monitor: Connessione interrotta dal corrispondente
2013-10-30 07:51:13.097+0000: 8296: debug : qemuMonitorIO:672 : Triggering error callback
2013-10-30 07:51:13.097+0000: 8296: debug : qemuProcessHandleMonitorError:351 : Received
error on 0x7fc1640eab80 'CentOS_30'
2013-10-30 07:51:13.097+0000: 8304: debug : qemuMonitorSend:899 : Send command resulted in
error Unable to read from monitor: Connessione interrotta dal corrispondente
2013-10-30 07:51:13.097+0000: 8304: debug : qemuProcessStop:3992 : Shutting down VM
'CentOS_30' pid=7655 flags=0
2013-10-30 07:51:13.097+0000: 8296: debug : qemuMonitorIO:638 : Error on monitor Unable to
read from monitor: Connessione interrotta dal corrispondente
2013-10-30 07:51:13.097+0000: 8296: debug : qemuMonitorIO:661 : Triggering EOF callback
6:52 a.m.
on 2013/10/31 06:24, Dan Kenigsberg wrote:
On Wed, Oct 30, 2013 at 08:41:43PM +0100, Alessandro Bianchi wrote:
> Il 30/10/2013 18:04, Dan Kenigsberg ha scritto:
>> On Wed, Oct 30, 2013 at 02:40:02PM +0100, Alessandro Bianchi wrote:
>>> Il 30/10/2013 13:58, Dan Kenigsberg ha scritto:
>>>
>>> On Wed, Oct 30, 2013 at 11:34:21AM +0100, Alessandro Bianchi wrote:
>>>
>>> Hi everyone
>>>
>>> I've set up a gluster storage with two replicated bricks
>>>
>>> DC is up and I created a VM to test gluster storage
>>>
>>> If I start the VM WITHOUT any disk attached (only one virtual DVD) it
>>> starts fine.
>>>
>>> If I attach a gluster domain disk thin provisioning 30 Gb the Vm stucks
in
>>> "waiting for launch" state
>>>
>>> I see no special activity on the gluster servers (they serve several
other
>>> shares with no troubles at all and even the ISO domain is a NFS on
>>> locally mounted gluster and works fine)
>>>
>>> I've double checked all the pre requisites and they look fine (F 19
-
>>> gluster setup insecure in both glusterd.vol and volume options -
>>> uid/gid/insecure )
>>>
>>> Am I doing something wrong?
>>>
>>> I'm even unable to stop the VM from the engine GUI
>>>
>>> Any advise?
>>>
>>> Which version of ovirt are you using? Hopefully ovirt-3.3.0.1.
>>> For how long is the VM stuck in its "wait for launch" state?
>>> What does `virsh -r list` has to say while startup stalls?
>>> Would you provide more content of your vdsm.log and possibly
>>> libvirtd.log so we can understand what blocks the VM start-up? Please
>>> use attachement of pastebin, as your mail agents wreaks havoc to the log
>>> lines.
>>>
>>>
>>> Thank you for your answer.
>>>
>>> Here are the "facts"
>>>
>>> In the GUI I see
>>>
>>> "waiting for launch 3 h"
>>>
>>> virsh -r list
>>> Id Nome Stato
>>> ----------------------------------------------------
>>> 3 CentOS_30 terminato
>>>
>>> vdsClient -s 0 list table
>>> 200dfb05-461e-49d9-95a2-c0a7c7ced669 0 CentOS_30
>>> WaitForLaunch
>>>
>>> Packages:
>>>
>>> ovirt-engine-userportal-3.3.0.1-1.fc19.noarch
>>> ovirt-log-collector-3.3.1-1.fc19.noarch
>>> ovirt-engine-restapi-3.3.0.1-1.fc19.noarch
>>> ovirt-engine-setup-3.3.0.1-1.fc19.noarch
>>> ovirt-engine-backend-3.3.0.1-1.fc19.noarch
>>> ovirt-host-deploy-java-1.1.1-1.fc19.noarch
>>> ovirt-release-fedora-8-1.noarch
>>> ovirt-engine-setup-plugin-allinone-3.3.0.1-1.fc19.noarch
>>> ovirt-engine-webadmin-portal-3.3.0.1-1.fc19.noarch
>>> ovirt-engine-sdk-python-3.3.0.7-1.fc19.noarch
>>> ovirt-iso-uploader-3.3.1-1.fc19.noarch
>>> ovirt-engine-websocket-proxy-3.3.0.1-1.fc19.noarch
>>> ovirt-engine-dbscripts-3.3.0.1-1.fc19.noarch
>>> ovirt-host-deploy-offline-1.1.1-1.fc19.noarch
>>> ovirt-engine-cli-3.3.0.5-1.fc19.noarch
>>> ovirt-engine-tools-3.3.0.1-1.fc19.noarch
>>> ovirt-engine-lib-3.3.0.1-1.fc19.noarch
>>> ovirt-image-uploader-3.3.1-1.fc19.noarch
>>> ovirt-engine-3.3.0.1-1.fc19.noarch
>>> ovirt-host-deploy-1.1.1-1.fc19.noarch
>>>
>>> I attach the full vdsm log
>>>
>>> Look around 30-10 10:30 to see all what happens
>>>
>>> Despite the "terminated" label in output from virsh I still see
the VM
>>> "waiting for launch" in the GUI, so I suspect the answer to
"how long" may
>>> be "forever"
>>>
>>> Since this is a test VM I can do whatever test you may need to track the
>>> problem included destroy and rebuild
>>>
>>> It would be great to have gluster support stable in ovirt!
>>>
>>> Thank you for your efforts
>> The log has an ominous failed attempt to start the VM, followed by an
>> immediate vdsm crash. Is it reproducible?
>>
>> We have plenty of issues lurking here:
>> 1. Why has libvirt failed to create the VM? For this, please find clues
>> in the complete non-line-broken CentOS_30.log and libvirtd.log.
> attached to this messages
>>
>> 2. Why was vdsm killed? Does /var/log/message has a clue from systemd?
> result of cat /var/log/messages | grep vdsm attached
I do not see an explicit attempt to take vdsmd down. Do you see any other
incriminating message correlated with
Oct 30 08:51:15 hypervisor respawn: slave '/usr/share/vdsm/vdsm' died, respawning
slave
>>
>> 3. We may have a nasty race: if Vdsm crashes just before it has
>> registered that the VM is down.
Actually, this is not the issue: vdsm tries (and fails, due to qemu/libvirt
bug) to destroy the VM.
>>
>> 4. We used to force Vdsm to run with LC_ALL=C. It seems that the grand
>> service rewrite by Zhou (http://gerrit.ovirt.org/15578) has changed
>> that. This may have adverse effects, since AFAIR we sometimes parse
>> application output, and assume that it's in C. Having a non-English
>> log file is problematic on it's own for support personal, used to
>> grep for keywords. ybronhei, was it intensional? Can it be reverted
>> or at least scrutinized?
> currentely it still says "waiting for launch 9h"
>
> I don't abort it so if you need any other info I can have them
libvirtd fails to connect to qemu's monitor. This smells like a qemu bug that
is beyond my over-the-mailing-list debugging abilities :-(
You may want to strace or gdb the running qemu process, or to try to re-attach
to it by restarting libvirtd.
2013-10-30 07:51:10.045+0000: 8304: debug : qemuProcessStart:3804 : Waiting for monitor
to show up
2013-10-30 07:51:10.045+0000: 8304: debug : qemuProcessWaitForMonitor:1707 : Connect
monitor to 0x7fc1640eab80 'CentOS_30'
2013-10-30 07:51:10.246+0000: 8304: debug : qemuMonitorOpenInternal:751 :
QEMU_MONITOR_NEW: mon=0x7fc1640ef6b0 refs=2 fd=27
2013-10-30 07:51:10.246+0000: 8304: debug : qemuMonitorSetCapabilities:1145 :
mon=0x7fc1640ef6b0
2013-10-30 07:51:10.246+0000: 8304: debug : qemuMonitorSend:887 : QEMU_MONITOR_SEND_MSG:
mon=0x7fc1640ef6b0
msg={"execute":"qmp_capabilities","id":"libvirt-1"}
fd=-1
2013-10-30 07:51:13.097+0000: 8296: error : qemuMonitorIORead:505 : Unable to read from
monitor: Connessione interrotta dal corrispondente
2013-10-30 07:51:13.097+0000: 8296: debug : qemuMonitorIO:638 : Error on monitor Unable
to read from monitor: Connessione interrotta dal corrispondente
2013-10-30 07:51:13.097+0000: 8296: debug : qemuMonitorIO:672 : Triggering error
callback
2013-10-30 07:51:13.097+0000: 8296: debug : qemuProcessHandleMonitorError:351 : Received
error on 0x7fc1640eab80 'CentOS_30'
2013-10-30 07:51:13.097+0000: 8304: debug : qemuMonitorSend:899 : Send command resulted
in error Unable to read from monitor: Connessione interrotta dal corrispondente
2013-10-30 07:51:13.097+0000: 8304: debug : qemuProcessStop:3992 : Shutting down VM
'CentOS_30' pid=7655 flags=0
2013-10-30 07:51:13.097+0000: 8296: debug : qemuMonitorIO:638 : Error on monitor Unable
to read from monitor: Connessione interrotta dal corrispondente
2013-10-30 07:51:13.097+0000: 8296: debug : qemuMonitorIO:661 : Triggering EOF callback
I noticed in the previous attached CentOS_30.log, qemu said "Gluster
connection failed for server=172.16.0.100" for each of the first few
attempts to start qemu. That's why libvirt said it could not connect to
qemu monitor, the real reason was that qemu process exited after it
checked the gluster storage. libvirt error message was not very friendly
in this case.
Then I see on "2013-10-30 08:28:51.047+0000" in CentOS_30.log, qemu
started successfully without reporting gluster error, this was fine. In
libvirtd.log on the corresponding time spot, it libvirt connected to the
monitor and reported it was about to issue a handshake.
Investigate the CentOS_30.log further, I find the attempts to start qemu
after "2013-10-30 08:28:51" were failed with the same error "Gluster
connection failed for server=172.16.0.100". Maybe there is a problem in
the gluster server or firewall? I'm not sure.
--
Thanks and best regards!
Zhou Zheng Sheng / 周征晟
E-mail: zhshzhou(a)linux.vnet.ibm.com
Telephone: 86-10-82454397
9:21 a.m.
On 10/31/2013 09:22 AM, Zhou Zheng Sheng wrote:
on 2013/10/31 06:24, Dan Kenigsberg wrote:
> On Wed, Oct 30, 2013 at 08:41:43PM +0100, Alessandro Bianchi wrote:
>> Il 30/10/2013 18:04, Dan Kenigsberg ha scritto:
>>> On Wed, Oct 30, 2013 at 02:40:02PM +0100, Alessandro Bianchi wrote:
>>>> Il 30/10/2013 13:58, Dan Kenigsberg ha scritto:
>>>>
>>>> On Wed, Oct 30, 2013 at 11:34:21AM +0100, Alessandro Bianchi wrote:
>>>>
>>>> Hi everyone
>>>>
>>>> I've set up a gluster storage with two replicated bricks
>>>>
>>>> DC is up and I created a VM to test gluster storage
>>>>
>>>> If I start the VM WITHOUT any disk attached (only one virtual DVD)
it
>>>> starts fine.
>>>>
>>>> If I attach a gluster domain disk thin provisioning 30 Gb the Vm
stucks in
>>>> "waiting for launch" state
>>>>
>>>> I see no special activity on the gluster servers (they serve several
other
>>>> shares with no troubles at all and even the ISO domain is a NFS on
>>>> locally mounted gluster and works fine)
>>>>
>>>> I've double checked all the pre requisites and they look fine (F
19 -
>>>> gluster setup insecure in both glusterd.vol and volume options -
>>>> uid/gid/insecure )
>>>>
>>>> Am I doing something wrong?
>>>>
>>>> I'm even unable to stop the VM from the engine GUI
>>>>
>>>> Any advise?
>>>>
>>>> Which version of ovirt are you using? Hopefully ovirt-3.3.0.1.
>>>> For how long is the VM stuck in its "wait for launch" state?
>>>> What does `virsh -r list` has to say while startup stalls?
>>>> Would you provide more content of your vdsm.log and possibly
>>>> libvirtd.log so we can understand what blocks the VM start-up? Please
>>>> use attachement of pastebin, as your mail agents wreaks havoc to the
log
>>>> lines.
>>>>
>>>>
>>>> Thank you for your answer.
>>>>
>>>> Here are the "facts"
>>>>
>>>> In the GUI I see
>>>>
>>>> "waiting for launch 3 h"
>>>>
>>>> virsh -r list
>>>> Id Nome Stato
>>>> ----------------------------------------------------
>>>> 3 CentOS_30 terminato
>>>>
>>>> vdsClient -s 0 list table
>>>> 200dfb05-461e-49d9-95a2-c0a7c7ced669 0 CentOS_30
>>>> WaitForLaunch
>>>>
>>>> Packages:
>>>>
>>>> ovirt-engine-userportal-3.3.0.1-1.fc19.noarch
>>>> ovirt-log-collector-3.3.1-1.fc19.noarch
>>>> ovirt-engine-restapi-3.3.0.1-1.fc19.noarch
>>>> ovirt-engine-setup-3.3.0.1-1.fc19.noarch
>>>> ovirt-engine-backend-3.3.0.1-1.fc19.noarch
>>>> ovirt-host-deploy-java-1.1.1-1.fc19.noarch
>>>> ovirt-release-fedora-8-1.noarch
>>>> ovirt-engine-setup-plugin-allinone-3.3.0.1-1.fc19.noarch
>>>> ovirt-engine-webadmin-portal-3.3.0.1-1.fc19.noarch
>>>> ovirt-engine-sdk-python-3.3.0.7-1.fc19.noarch
>>>> ovirt-iso-uploader-3.3.1-1.fc19.noarch
>>>> ovirt-engine-websocket-proxy-3.3.0.1-1.fc19.noarch
>>>> ovirt-engine-dbscripts-3.3.0.1-1.fc19.noarch
>>>> ovirt-host-deploy-offline-1.1.1-1.fc19.noarch
>>>> ovirt-engine-cli-3.3.0.5-1.fc19.noarch
>>>> ovirt-engine-tools-3.3.0.1-1.fc19.noarch
>>>> ovirt-engine-lib-3.3.0.1-1.fc19.noarch
>>>> ovirt-image-uploader-3.3.1-1.fc19.noarch
>>>> ovirt-engine-3.3.0.1-1.fc19.noarch
>>>> ovirt-host-deploy-1.1.1-1.fc19.noarch
>>>>
>>>> I attach the full vdsm log
>>>>
>>>> Look around 30-10 10:30 to see all what happens
>>>>
>>>> Despite the "terminated" label in output from virsh I still
see the VM
>>>> "waiting for launch" in the GUI, so I suspect the answer to
"how long" may
>>>> be "forever"
>>>>
>>>> Since this is a test VM I can do whatever test you may need to track
the
>>>> problem included destroy and rebuild
>>>>
>>>> It would be great to have gluster support stable in ovirt!
>>>>
>>>> Thank you for your efforts
>>> The log has an ominous failed attempt to start the VM, followed by an
>>> immediate vdsm crash. Is it reproducible?
>>>
>>> We have plenty of issues lurking here:
>>> 1. Why has libvirt failed to create the VM? For this, please find clues
>>> in the complete non-line-broken CentOS_30.log and libvirtd.log.
>> attached to this messages
>>> 2. Why was vdsm killed? Does /var/log/message has a clue from systemd?
>> result of cat /var/log/messages | grep vdsm attached
> I do not see an explicit attempt to take vdsmd down. Do you see any other
> incriminating message correlated with
>
> Oct 30 08:51:15 hypervisor respawn: slave '/usr/share/vdsm/vdsm' died,
respawning slave
>
>
>>> 3. We may have a nasty race: if Vdsm crashes just before it has
>>> registered that the VM is down.
> Actually, this is not the issue: vdsm tries (and fails, due to qemu/libvirt
> bug) to destroy the VM.
>
>>> 4. We used to force Vdsm to run with LC_ALL=C. It seems that the grand
>>> service rewrite by Zhou (http://gerrit.ovirt.org/15578) has changed
>>> that. This may have adverse effects, since AFAIR we sometimes parse
>>> application output, and assume that it's in C. Having a non-English
>>> log file is problematic on it's own for support personal, used to
>>> grep for keywords. ybronhei, was it intensional? Can it be reverted
>>> or at least scrutinized?
>> currentely it still says "waiting for launch 9h"
>>
>> I don't abort it so if you need any other info I can have them
> libvirtd fails to connect to qemu's monitor. This smells like a qemu bug that
> is beyond my over-the-mailing-list debugging abilities :-(
> You may want to strace or gdb the running qemu process, or to try to re-attach
> to it by restarting libvirtd.
>
> 2013-10-30 07:51:10.045+0000: 8304: debug : qemuProcessStart:3804 : Waiting for
monitor to show up
> 2013-10-30 07:51:10.045+0000: 8304: debug : qemuProcessWaitForMonitor:1707 : Connect
monitor to 0x7fc1640eab80 'CentOS_30'
> 2013-10-30 07:51:10.246+0000: 8304: debug : qemuMonitorOpenInternal:751 :
QEMU_MONITOR_NEW: mon=0x7fc1640ef6b0 refs=2 fd=27
> 2013-10-30 07:51:10.246+0000: 8304: debug : qemuMonitorSetCapabilities:1145 :
mon=0x7fc1640ef6b0
> 2013-10-30 07:51:10.246+0000: 8304: debug : qemuMonitorSend:887 :
QEMU_MONITOR_SEND_MSG: mon=0x7fc1640ef6b0
msg={"execute":"qmp_capabilities","id":"libvirt-1"}
>
> fd=-1
> 2013-10-30 07:51:13.097+0000: 8296: error : qemuMonitorIORead:505 : Unable to read
from monitor: Connessione interrotta dal corrispondente
> 2013-10-30 07:51:13.097+0000: 8296: debug : qemuMonitorIO:638 : Error on monitor
Unable to read from monitor: Connessione interrotta dal corrispondente
> 2013-10-30 07:51:13.097+0000: 8296: debug : qemuMonitorIO:672 : Triggering error
callback
> 2013-10-30 07:51:13.097+0000: 8296: debug : qemuProcessHandleMonitorError:351 :
Received error on 0x7fc1640eab80 'CentOS_30'
> 2013-10-30 07:51:13.097+0000: 8304: debug : qemuMonitorSend:899 : Send command
resulted in error Unable to read from monitor: Connessione interrotta dal corrispondente
> 2013-10-30 07:51:13.097+0000: 8304: debug : qemuProcessStop:3992 : Shutting down VM
'CentOS_30' pid=7655 flags=0
> 2013-10-30 07:51:13.097+0000: 8296: debug : qemuMonitorIO:638 : Error on monitor
Unable to read from monitor: Connessione interrotta dal corrispondente
> 2013-10-30 07:51:13.097+0000: 8296: debug : qemuMonitorIO:661 : Triggering EOF
callback
>
I noticed in the previous attached CentOS_30.log, qemu said "Gluster
connection failed for server=172.16.0.100" for each of the first few
attempts to start qemu. That's why libvirt said it could not connect to
qemu monitor, the real reason was that qemu process exited after it
checked the gluster storage. libvirt error message was not very friendly
in this case.
Then I see on "2013-10-30 08:28:51.047+0000" in CentOS_30.log, qemu
started successfully without reporting gluster error, this was fine. In
libvirtd.log on the corresponding time spot, it libvirt connected to the
monitor and reported it was about to issue a handshake.
Investigate the CentOS_30.log further, I find the attempts to start qemu
after "2013-10-30 08:28:51" were failed with the same error "Gluster
connection failed for server=172.16.0.100". Maybe there is a problem in
the gluster server or firewall? I'm not sure.
http://www.ovirt.org/Features/GlusterFS_Storage_Domain#Important_Pre-requ... - I
assume these have been followed w.r.t setting permissions.
10:02 a.m.
On 10/31/2013 11:51 AM, Sahina Bose wrote:
On 10/31/2013 09:22 AM, Zhou Zheng Sheng wrote:
>
> on 2013/10/31 06:24, Dan Kenigsberg wrote:
>> On Wed, Oct 30, 2013 at 08:41:43PM +0100, Alessandro Bianchi wrote:
>>> Il 30/10/2013 18:04, Dan Kenigsberg ha scritto:
>>>> On Wed, Oct 30, 2013 at 02:40:02PM +0100, Alessandro Bianchi wrote:
>>>>> Il 30/10/2013 13:58, Dan Kenigsberg ha scritto:
>>>>>
>>>>> On Wed, Oct 30, 2013 at 11:34:21AM +0100, Alessandro Bianchi
>>>>> wrote:
>>>>>
>>>>> Hi everyone
>>>>>
>>>>> I've set up a gluster storage with two replicated bricks
>>>>>
>>>>> DC is up and I created a VM to test gluster storage
>>>>>
>>>>> If I start the VM WITHOUT any disk attached (only one
>>>>> virtual DVD) it
>>>>> starts fine.
>>>>>
>>>>> If I attach a gluster domain disk thin provisioning 30 Gb
>>>>> the Vm stucks in
>>>>> "waiting for launch" state
>>>>>
>>>>> I see no special activity on the gluster servers (they serve
>>>>> several other
>>>>> shares with no troubles at all and even the ISO domain is a
>>>>> NFS on
>>>>> locally mounted gluster and works fine)
>>>>>
>>>>> I've double checked all the pre requisites and they look
>>>>> fine (F 19 -
>>>>> gluster setup insecure in both glusterd.vol and volume
>>>>> options -
>>>>> uid/gid/insecure )
>>>>>
>>>>> Am I doing something wrong?
>>>>>
>>>>> I'm even unable to stop the VM from the engine GUI
>>>>>
>>>>> Any advise?
>>>>>
>>>>> Which version of ovirt are you using? Hopefully ovirt-3.3.0.1.
>>>>> For how long is the VM stuck in its "wait for launch"
state?
>>>>> What does `virsh -r list` has to say while startup stalls?
>>>>> Would you provide more content of your vdsm.log and possibly
>>>>> libvirtd.log so we can understand what blocks the VM start-up?
>>>>> Please
>>>>> use attachement of pastebin, as your mail agents wreaks havoc
>>>>> to the log
>>>>> lines.
>>>>>
>>>>>
>>>>> Thank you for your answer.
>>>>>
>>>>> Here are the "facts"
>>>>>
>>>>> In the GUI I see
>>>>>
>>>>> "waiting for launch 3 h"
>>>>>
>>>>> virsh -r list
>>>>> Id Nome Stato
>>>>> ----------------------------------------------------
>>>>> 3 CentOS_30 terminato
>>>>>
>>>>> vdsClient -s 0 list table
>>>>> 200dfb05-461e-49d9-95a2-c0a7c7ced669 0 CentOS_30
>>>>> WaitForLaunch
>>>>>
>>>>> Packages:
>>>>>
>>>>> ovirt-engine-userportal-3.3.0.1-1.fc19.noarch
>>>>> ovirt-log-collector-3.3.1-1.fc19.noarch
>>>>> ovirt-engine-restapi-3.3.0.1-1.fc19.noarch
>>>>> ovirt-engine-setup-3.3.0.1-1.fc19.noarch
>>>>> ovirt-engine-backend-3.3.0.1-1.fc19.noarch
>>>>> ovirt-host-deploy-java-1.1.1-1.fc19.noarch
>>>>> ovirt-release-fedora-8-1.noarch
>>>>> ovirt-engine-setup-plugin-allinone-3.3.0.1-1.fc19.noarch
>>>>> ovirt-engine-webadmin-portal-3.3.0.1-1.fc19.noarch
>>>>> ovirt-engine-sdk-python-3.3.0.7-1.fc19.noarch
>>>>> ovirt-iso-uploader-3.3.1-1.fc19.noarch
>>>>> ovirt-engine-websocket-proxy-3.3.0.1-1.fc19.noarch
>>>>> ovirt-engine-dbscripts-3.3.0.1-1.fc19.noarch
>>>>> ovirt-host-deploy-offline-1.1.1-1.fc19.noarch
>>>>> ovirt-engine-cli-3.3.0.5-1.fc19.noarch
>>>>> ovirt-engine-tools-3.3.0.1-1.fc19.noarch
>>>>> ovirt-engine-lib-3.3.0.1-1.fc19.noarch
>>>>> ovirt-image-uploader-3.3.1-1.fc19.noarch
>>>>> ovirt-engine-3.3.0.1-1.fc19.noarch
>>>>> ovirt-host-deploy-1.1.1-1.fc19.noarch
>>>>>
>>>>> I attach the full vdsm log
>>>>>
>>>>> Look around 30-10 10:30 to see all what happens
>>>>>
>>>>> Despite the "terminated" label in output from virsh I
still
>>>>> see the VM
>>>>> "waiting for launch" in the GUI, so I suspect the
answer to
>>>>> "how long" may
>>>>> be "forever"
>>>>>
>>>>> Since this is a test VM I can do whatever test you may need
>>>>> to track the
>>>>> problem included destroy and rebuild
>>>>>
>>>>> It would be great to have gluster support stable in ovirt!
>>>>>
>>>>> Thank you for your efforts
>>>> The log has an ominous failed attempt to start the VM, followed by an
>>>> immediate vdsm crash. Is it reproducible?
>>>>
>>>> We have plenty of issues lurking here:
>>>> 1. Why has libvirt failed to create the VM? For this, please find
>>>> clues
>>>> in the complete non-line-broken CentOS_30.log and libvirtd.log.
>>> attached to this messages
>>>> 2. Why was vdsm killed? Does /var/log/message has a clue from
>>>> systemd?
>>> result of cat /var/log/messages | grep vdsm attached
>> I do not see an explicit attempt to take vdsmd down. Do you see any
>> other
>> incriminating message correlated with
>>
>> Oct 30 08:51:15 hypervisor respawn: slave '/usr/share/vdsm/vdsm'
>> died, respawning slave
>>
>>
>>>> 3. We may have a nasty race: if Vdsm crashes just before it has
>>>> registered that the VM is down.
>> Actually, this is not the issue: vdsm tries (and fails, due to
>> qemu/libvirt
>> bug) to destroy the VM.
>>
>>>> 4. We used to force Vdsm to run with LC_ALL=C. It seems that the
>>>> grand
>>>> service rewrite by Zhou (http://gerrit.ovirt.org/15578) has
>>>> changed
>>>> that. This may have adverse effects, since AFAIR we sometimes
>>>> parse
>>>> application output, and assume that it's in C. Having a
>>>> non-English
>>>> log file is problematic on it's own for support personal, used
to
>>>> grep for keywords. ybronhei, was it intensional? Can it be
>>>> reverted
>>>> or at least scrutinized?
>>> currentely it still says "waiting for launch 9h"
>>>
>>> I don't abort it so if you need any other info I can have them
>> libvirtd fails to connect to qemu's monitor. This smells like a qemu
>> bug that
>> is beyond my over-the-mailing-list debugging abilities :-(
>> You may want to strace or gdb the running qemu process, or to try to
>> re-attach
>> to it by restarting libvirtd.
>>
>> 2013-10-30 07:51:10.045+0000: 8304: debug : qemuProcessStart:3804 :
>> Waiting for monitor to show up
>> 2013-10-30 07:51:10.045+0000: 8304: debug :
>> qemuProcessWaitForMonitor:1707 : Connect monitor to 0x7fc1640eab80
>> 'CentOS_30'
>> 2013-10-30 07:51:10.246+0000: 8304: debug :
>> qemuMonitorOpenInternal:751 : QEMU_MONITOR_NEW: mon=0x7fc1640ef6b0
>> refs=2 fd=27
>> 2013-10-30 07:51:10.246+0000: 8304: debug :
>> qemuMonitorSetCapabilities:1145 : mon=0x7fc1640ef6b0
>> 2013-10-30 07:51:10.246+0000: 8304: debug : qemuMonitorSend:887 :
>> QEMU_MONITOR_SEND_MSG: mon=0x7fc1640ef6b0
>>
msg={"execute":"qmp_capabilities","id":"libvirt-1"}
>>
>> fd=-1
>> 2013-10-30 07:51:13.097+0000: 8296: error : qemuMonitorIORead:505 :
>> Unable to read from monitor: Connessione interrotta dal corrispondente
>> 2013-10-30 07:51:13.097+0000: 8296: debug : qemuMonitorIO:638 :
>> Error on monitor Unable to read from monitor: Connessione interrotta
>> dal corrispondente
>> 2013-10-30 07:51:13.097+0000: 8296: debug : qemuMonitorIO:672 :
>> Triggering error callback
>> 2013-10-30 07:51:13.097+0000: 8296: debug :
>> qemuProcessHandleMonitorError:351 : Received error on 0x7fc1640eab80
>> 'CentOS_30'
>> 2013-10-30 07:51:13.097+0000: 8304: debug : qemuMonitorSend:899 :
>> Send command resulted in error Unable to read from monitor:
>> Connessione interrotta dal corrispondente
>> 2013-10-30 07:51:13.097+0000: 8304: debug : qemuProcessStop:3992 :
>> Shutting down VM 'CentOS_30' pid=7655 flags=0
>> 2013-10-30 07:51:13.097+0000: 8296: debug : qemuMonitorIO:638 :
>> Error on monitor Unable to read from monitor: Connessione interrotta
>> dal corrispondente
>> 2013-10-30 07:51:13.097+0000: 8296: debug : qemuMonitorIO:661 :
>> Triggering EOF callback
>>
> I noticed in the previous attached CentOS_30.log, qemu said "Gluster
> connection failed for server=172.16.0.100" for each of the first few
> attempts to start qemu. That's why libvirt said it could not connect to
> qemu monitor, the real reason was that qemu process exited after it
> checked the gluster storage. libvirt error message was not very friendly
> in this case.
>
> Then I see on "2013-10-30 08:28:51.047+0000" in CentOS_30.log, qemu
> started successfully without reporting gluster error, this was fine. In
> libvirtd.log on the corresponding time spot, it libvirt connected to the
> monitor and reported it was about to issue a handshake.
>
> Investigate the CentOS_30.log further, I find the attempts to start qemu
> after "2013-10-30 08:28:51" were failed with the same error "Gluster
> connection failed for server=172.16.0.100". Maybe there is a problem in
> the gluster server or firewall? I'm not sure.
>
http://www.ovirt.org/Features/GlusterFS_Storage_Domain#Important_Pre-requ...
- I assume these have been followed w.r.t setting permissions.
Sorry, I missed that you had set all the insecure options on the volume.
"Gluster connection failed for server" has a "Transport endpoint is not
connected" error message.
Are you able to manually mount the gluster volume?
_______________________________________________
Users mailing list
Users(a)ovirt.org
http://lists.ovirt.org/mailman/listinfo/users
4040
days inactive
4041
days old
11 comments
5 participants
participants (5)
-
Alessandro Bianchi -
Dan Kenigsberg -
Omer Frenkel -
Sahina Bose -
Zhou Zheng Sheng