Re: [Users] Gluster VM stuck in "waiting for launch" state
------=_Part_14839104_1553755466.1383132645323 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable ----- Original Message -----
From: "Alessandro Bianchi" <a.bianchi@skynet.it> To: users@ovirt.org Sent: Wednesday, October 30, 2013 12:49:27 PM Subject: Re: [Users] Gluster VM stuck in "waiting for launch" state
Thank you for your answer: yes it's marked as up
From: "Alessandro Bianchi" <a.bianchi@skynet.it> To: users@ovirt.org Sent: Wednesday, October 30, 2013 12:34:21 PM =20 =20 Subject: [Users] Gluster VM stuck in "waiting for launch" state =20 =20
Hi everyone =20 =20
I've set up a gluster storage with two replicated bricks =20 =20
DC is up and I created a VM to test gluster storage =20 =20
If I start the VM WITHOUT any disk attached (only one virtual DVD) it starts =20 =20 fine. =20 =20
If I attach a gluster domain disk thin provisioning 30 Gb the Vm stuc= ks in =20 =20 "waiting for launch" state =20 =20
I see no special activity on the gluster servers (they serve several other =20 =20 shares with no troubles at all and even the ISO domain is a NFS on locally =20 =20 mounted gluster and works fine) =20 =20
I've double checked all the pre requisites and they look fine (F 19 - gluster =20 =20 setup insecure in both glusterd.vol and volume options - uid/gid/inse= cure ) =20 =20
Am I doing something wrong? =20 =20
I'm even unable to stop the VM from the engine GUI =20 =20
Any advise? =20 =20
what is the status of the host that runs the vm? =20 is it up? =20
Yes
greate what does vdsClient returns for this vm status?=20 (you can use:=20 vdsClient -s 0 list table=20 or if you work in non-secure setup:=20 vdsClient 0 list table=20 )=20
Thank you =20 =20
Best regards =20 =20
CentOS_30.log =20 =20
2013-10-30 10:17:48.094+0000: starting up =20 =20 LC_ALL=3DC PATH=3D/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin =20 =20 QEMU_AUDIO_DRV=3Dspice /usr/bin/qemu-kvm -name CentOS_30 -S -machine =20 =20 pc-1.0,accel=3Dkvm,usb=3Doff -cpu Westmere -m 2048 -smp =20 =20 1,sockets=3D1,cores=3D1,threads=3D1 -uuid 200dfb05-461e-49d9-95a2-c0a= 7c7ced669 =20 =20 -smbios type=3D1,manufacturer=3DoVirt,product=3DoVirt =20 =20 Node,version=3D19-4,serial=3D316140A0-D7DA-11DD-AF75-08606ED667F7,uui= d=3D200dfb05-461e-49d9-95a2-c0a7c7ced669 =20 =20 -no-user-config -nodefaults -chardev =20 =20 socket,id=3Dcharmonitor,path=3D/var/lib/libvirt/qemu/CentOS_30.monito= r,server,nowait =20 =20 -mon chardev=3Dcharmonitor,id=3Dmonitor,mode=3Dcontrol -rtc =20 =20 base=3D2013-10-30T10:17:47,driftfix=3Dslew -no-shutdown -device =20 =20 piix3-usb-uhci,id=3Dusb,bus=3Dpci.0,addr=3D0x1.0x2 -device =20 =20 virtio-scsi-pci,id=3Dscsi0,bus=3Dpci.0,addr=3D0x4 -device =20 =20 virtio-serial-pci,id=3Dvirtio-serial0,bus=3Dpci.0,addr=3D0x5 -drive =20 =20 file=3D/rhev/data-center/mnt/172.16.0.5:_home_iso2/8e56a914-3395-48ad= -ab4c-c2ca7f9956b4/images/11111111-1111-1111-1111-111111111111/CentOS-6.4-x= 86_64-bin-DVD1.iso,if=3Dnone,id=3Ddrive-ide0-1-0,readonly=3Don,format=3Draw= ,serial=3D =20 =20 -device ide-cd,bus=3Dide.1,unit=3D0,drive=3Ddrive-ide0-1-0,id=3Dide0-1-0,boot= index=3D1 =20 =20 -drive =20 =20 file=3Dgluster://172.16.0.100/vms/21e3d67f-fdec-4f87-b09e-53af994a6f8= 7/images/b73a79fe-401b-434c-b023-6de4c3eb100d/202adc86-7857-40eb-8ca6-7cec3= ef0d2d6,if=3Dnone,id=3Ddrive-virtio-disk0,format=3Draw,serial=3Db73a79fe-40= 1b-434c-b023-6de4c3eb100d,cache=3Dnone,werror=3Dstop,rerror=3Dstop,aio=3Dth= reads =20 =20 -device =20 =20 virtio-blk-pci,scsi=3Doff,bus=3Dpci.0,addr=3D0x6,drive=3Ddrive-virtio= -disk0,id=3Dvirtio-disk0,bootindex=3D2 =20 =20 -netdev tap,fd=3D27,id=3Dhostnet0,vhost=3Don,vhostfd=3D28 -device =20 =20 virtio-net-pci,netdev=3Dhostnet0,id=3Dnet0,mac=3D00:1a:4a:00:00:33,bu= s=3Dpci.0,addr=3D0x3,bootindex=3D3 =20 =20 -chardev =20 =20 socket,id=3Dcharchannel0,path=3D/var/lib/libvirt/qemu/channels/200dfb= 05-461e-49d9-95a2-c0a7c7ced669.com.redhat.rhevm.vdsm,server,nowait =20 =20 -device =20 =20 virtserialport,bus=3Dvirtio-serial0.0,nr=3D1,chardev=3Dcharchannel0,i= d=3Dchannel0,name=3Dcom.redhat.rhevm.vdsm =20 =20 -chardev =20 =20 socket,id=3Dcharchannel1,path=3D/var/lib/libvirt/qemu/channels/200dfb= 05-461e-49d9-95a2-c0a7c7ced669.org.qemu.guest_agent.0,server,nowait =20 =20 -device =20 =20 virtserialport,bus=3Dvirtio-serial0.0,nr=3D2,chardev=3Dcharchannel1,i= d=3Dchannel1,name=3Dorg.qemu.guest_agent.0 =20 =20 -chardev spicevmc,id=3Dcharchannel2,name=3Dvdagent -device =20 =20 virtserialport,bus=3Dvirtio-serial0.0,nr=3D3,chardev=3Dcharchannel2,i= d=3Dchannel2,name=3Dcom.redhat.spice.0 =20 =20 -spice =20 =20 tls-port=3D5900,addr=3D0,x509-dir=3D/etc/pki/vdsm/libvirt-spice,tls-c= hannel=3Dmain,tls-channel=3Ddisplay,tls-channel=3Dinputs,tls-channel=3Dcurs= or,tls-channel=3Dplayback,tls-channel=3Drecord,tls-channel=3Dsmartcard,tls-= channel=3Dusbredir,seamless-migration=3Don =20 =20 -k en-us -vga qxl -global qxl-vga.ram_size=3D67108864 -global =20 =20 qxl-vga.vram_size=3D67108864 -device virtio-balloon-pci,id=3Dballoon0= ,bus=3Dpci =20 =20
vdsm.log =20 =20
Thread-1239::DEBUG::2013-10-30 =20 =20 11:25:03,420::task::974::TaskManager.Task::(_decref) =20 =20 Task=3D`d891f3d3-070d-403f-9050-f10651a7fc47`::ref 0 aborting False =20 =20 Thread-242::DEBUG::2013-10-30 =20 =20 11:25:04,982::domainMonitor::178::Storage.DomainMonitorThread::(_moni= torDomain) =20 =20 Refreshing domain 21e3d67f-fdec-4f87-b09e-53af994a6f87 =20 =20 Thread-242::DEBUG::2013-10-30 =20 =20 11:25:04,992::fileSD::153::Storage.StorageDomain::(__init__) Reading domain =20 =20 in path =20 =20 /rhev/data-center/mnt/glusterSD/172.16.0.100:vms/21e3d67f-fdec-4f87-b= 09e-53af994a6f87 =20 =20 Thread-242::DEBUG::2013-10-30 =20 =20 11:25:04,994::persistentDict::192::Storage.PersistentDict::(__init__) =20 =20 Created a persistent dict with FileMetadataRW backend =20 =20 Thread-242::DEBUG::2013-10-30 =20 =20 11:25:05,005::persistentDict::234::Storage.PersistentDict::(refresh) = read =20 =20 lines (FileMetadataRW)=3D['CLASS=3DData', 'DESCRIPTION=3Dvms', =20 =20 'IOOPTIMEOUTSEC=3D10', 'LEASERETRIES=3D3', 'LEASETIMESEC=3D60', 'LOCK= POLICY=3D', =20 =20 'LOCKRENEWALINTERVALSEC=3D5', 'MASTER_VERSION=3D1', =20 =20 'POOL_DESCRIPTION=3DGlusterSD', =20 =20 'POOL_DOMAINS=3D21e3d67f-fdec-4f87-b09e-53af994a6f87:Active,8e56a914-= 3395-48ad-ab4c-c2ca7f9956b4:Active', =20 =20 'POOL_SPM_ID=3D1', 'POOL_SPM_LVER=3D3', =20 =20 'POOL_UUID=3De3cb7694-47f7-4eac-9201-922e381a25dc', =20 =20 'REMOTE_PATH=3D172.16.0.100:vms', 'ROLE=3DMaster', =20 =20 'SDUUID=3D21e3d67f-fdec-4f87-b09e-53af994a6f87', 'TYPE=3DGLUSTERFS', =20 =20 'VERSION=3D3', '_SHA_CKSUM=3D2d0dc3836063d45dd1d8046aaf00bce05c2455ea= '] =20 =20 Thread-242::DEBUG::2013-10-30 =20 =20 11:25:05,008::fileSD::535::Storage.StorageDomain::(imageGarbageCollec= tor) =20 =20 Removing remnants of deleted images [] =20 =20 Thread-242:: INFO::2013-10-30 11:25:05,008::sd::374::Storage.StorageDomain::(_registerResourceNames= paces) =20 =20 Resource namespace 21e3d67f-fdec-4f87-b09e-53af994a6f87_imageNS alrea= dy =20 =20 registered =20 =20 Thread-242:: INFO::2013-10-30 11:25:05,008::sd::382::Storage.StorageDomain::(_registerResourceNames= paces) =20 =20 Resource namespace 21e3d67f-fdec-4f87-b09e-53af994a6f87_volumeNS alre= ady =20 =20 registered =20 =20 Thread-242::DEBUG::2013-10-30 =20 =20 11:25:05,020::fileSD::238::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd =20 =20 iflag=3Ddirect =20 =20 if=3D/rhev/data-center/mnt/glusterSD/172.16.0.100:vms/21e3d67f-fdec-4= f87-b09e-53af994a6f87/dom_md/metadata =20 =20 bs=3D4096 count=3D1' (cwd None) =20 =20 Thread-242::DEBUG::2013-10-30 =20 =20 11:25:05,026::fileSD::238::Storage.Misc.excCmd::(getReadDelay) SUCCES= S: =20 =20 <err> =3D '0+1 records in\n0+1 records out\n497 bytes (497 B) copied, =20 =20 0.000280701 s, 1.8 MB/s\n'; <rc> =3D 0 =20 =20 Thread-243::DEBUG::2013-10-30 =20 =20 11:25:07,721::domainMonitor::178::Storage.DomainMonitorThread::(_moni= torDomain) =20 =20 Refreshing domain 8e56a914-3395-48ad-ab4c-c2ca7f9956b4 =20 =20 Thread-243::DEBUG::2013-10-30 =20 =20 11:25:07,730::fileSD::153::Storage.StorageDomain::(__init__) Reading domain =20 =20 in path =20 =20 /rhev/data-center/mnt/172.16.0.5:_home_iso2/8e56a914-3395-48ad-ab4c-c= 2ca7f9956b4 =20 =20 Thread-243::DEBUG::2013-10-30 =20 =20 11:25:07,731::persistentDict::192::Storage.PersistentDict::(__init__) =20 =20 Created a persistent dict with FileMetadataRW backend =20 =20 Thread-243::DEBUG::2013-10-30 =20 =20 11:25:07,740::persistentDict::234::Storage.PersistentDict::(refresh) = read =20 =20 lines (FileMetadataRW)=3D['CLASS=3DIso', 'DESCRIPTION=3DISO', 'IOOPTIMEOUTSEC=3D1', =20 =20 'LEASERETRIES=3D3', 'LEASETIMESEC=3D5', 'LOCKPOLICY=3D', =20 =20 'LOCKRENEWALINTERVALSEC=3D5', 'MASTER_VERSION=3D0', =20 =20 'POOL_UUID=3D01b79582-75e3-436d-bade-db653207620b,e3cb7694-47f7-4eac-= 9201-922e381a25dc', =20 =20 'REMOTE_PATH=3D172.16.0.5:/home/iso2', 'ROLE=3DRegular', =20 =20 'SDUUID=3D8e56a914-3395-48ad-ab4c-c2ca7f9956b4', 'TYPE=3DNFS', 'VERSI= ON=3D0', =20 =20 '_SHA_CKSUM=3Db0d102325f279bb8efa68c594cbace0b11c66783'] =20 =20 Thread-243::DEBUG::2013-10-30 =20 =20 11:25:07,741::fileSD::535::Storage.StorageDomain::(imageGarbageCollec= tor) =20 =20 Removing remnants of deleted images [] =20 =20 Thread-243:: INFO::2013-10-30 11:25:07,741::sd::374::Storage.StorageDomain::(_registerResourceNames= paces) =20 =20 Resource namespace 8e56a914-3395-48ad-ab4c-c2ca7f9956b4_imageNS alrea= dy =20 =20 registered =20 =20 Thread-243:: INFO::2013-10-30 11:25:07,741::sd::382::Storage.StorageDomain::(_registerResourceNames= paces) =20 =20 Resource namespace 8e56a914-3395-48ad-ab4c-c2ca7f9956b4_volumeNS alre= ady =20 =20 registered =20 =20 Thread-243::DEBUG::2013-10-30 =20 =20 11:25:07,757::fileSD::238::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd =20 =20 iflag=3Ddirect =20 =20 if=3D/rhev/data-center/mnt/172.16.0.5:_home_iso2/8e56a914-3395-48ad-a= b4c-c2ca7f9956b4/dom_md/metadata =20 =20 bs=3D4096 count=3D1' (cwd None) =20 =20 Thread-243::DEBUG::2013-10-30 =20 =20 11:25:07,760::fileSD::238::Storage.Misc.excCmd::(getReadDelay) SUCCES= S: =20 =20 <err> =3D '0+1 records in\n0+1 records out\n373 bytes (373 B) copied, =20 =20 0.000128829 s, 2.9 MB/s\n'; <rc> =3D 0 =20 =20 Thread-1246::DEBUG::2013-10-30 =20 =20 11:25:09,944::task::579::TaskManager.Task::(_updateState) =20 =20 Task=3D`c064522b-6fe7-4cb2-b85d-ad1f8185919a`::moving from state init= -> state =20 =20 preparing =20 =20 Thread-1246:: INFO::2013-10-30 11:25:09,944::logUtils::44::dispatcher::(wrapper) Run and protect: =20 =20 repoStats(options=3DNone) =20 =20 Thread-1246:: INFO::2013-10-30 11:25:09,945::logUtils::47::dispatcher::(wrapper) Run and protect: =20 =20 repoStats, Return response: {'21e3d67f-fdec-4f87-b09e-53af994a6f87': =20 =20 {'delay': '0.000280701', 'lastCheck': '4.9', 'code': 0, 'valid': True= , =20 =20 'version': 3}, '8e56a914-3395-48ad-ab4c-c2ca7f9956b4': {'delay': =20 =20 '0.000128829', 'lastCheck': '2.2', 'code': 0, 'valid': True, 'version= ': 0}} =20 =20 Thread-1246::DEBUG::2013-10-30 =20 =20 11:25:09,945::task::1168::TaskManager.Task::(prepare) =20 =20 Task=3D`c064522b-6fe7-4cb2-b85d-ad1f8185919a`::finished: =20 =20 {'21e3d67f-fdec-4f87-b09e-53af994a6f87': {'delay': '0.000280701', =20 =20 'lastCheck': '4.9', 'code': 0, 'valid': True, 'version': 3}, =20 =20 '8e56a914-3395-48ad-ab4c-c2ca7f9956b4': {'delay': '0.000128829', =20 =20 'lastCheck': '2.2', 'code': 0, 'valid': True, 'version': 0}} =20 =20 Thread-1246::DEBUG::2013-10-30 =20 =20 11:25:09,945::task::579::TaskManager.Task::(_updateState) =20 =20 Task=3D`c064522b-6fe7-4cb2-b85d-ad1f8185919a`::moving from state prep= aring -> =20 =20 state finished =20 =20 Thread-1246::DEBUG::2013-10-30 =20 =20 11:25:09,945::resourceManager::939::ResourceManager.Owner::(releaseAl= l) =20 =20 Owner.releaseAll requests {} resources {} =20 =20 Thread-1246::DEBUG::2013-10-30 =20 =20 11:25:09,945::resourceManager::976::ResourceManager.Owner::(cancelAll= ) =20 =20 Owner.cancelAll requests {} =20 =20 Thread-1246::DEBUG::2013-10-30 =20 =20 11:25:09,945::task::974::TaskManager.Task::(_decref) =20 =20 Task=3D`c064522b-6fe7-4cb2-b85d-ad1f8185919a`::ref 0 aborting False =20 =20 Thread-1249::DEBUG::2013-10-30 =20 =20 11:25:13,507::BindingXMLRPC::177::vds::(wrapper) client [172.16.0.5] =20 =20 Thread-1249::DEBUG::2013-10-30 =20 =20 11:25:13,507::task::579::TaskManager.Task::(_updateState) =20 =20 Task=3D`8518162d-eb91-44aa-819a-354e05807cb9`::moving from state init= -> state =20 =20 preparing =20 =20 Thread-1249:: INFO::2013-10-30 11:25:13,507::logUtils::44::dispatcher::(wrapper) Run and protect: =20 =20 getSpmStatus(spUUID=3D'e3cb7694-47f7-4eac-9201-922e381a25dc', options= =3DNone) =20 =20 Thread-1249:: INFO::2013-10-30 11:25:13,508::logUtils::47::dispatcher::(wrapper) Run and protect: =20 =20 getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', =20 =20 'spmLver': 3}} =20 =20 Thread-1249::DEBUG::2013-10-30 =20 =20 11:25:13,508::task::1168::TaskManager.Task::(prepare) =20 =20 Task=3D`8518162d-eb91-44aa-819a-354e05807cb9`::finished: {'spm_st': {'spmId': =20 =20 1, 'spmStatus': 'SPM', 'spmLver': 3}} =20 =20 Thread-1249::DEBUG::2013-10-30 =20 =20 11:25:13,508::task::579::TaskManager.Task::(_updateState) =20 =20 Task=3D`8518162d-eb91-44aa-819a-354e05807cb9`::moving from state prep= aring -> =20 =20 state finished =20 =20 Thread-1249::DEBUG::2013-10-30 =20 =20 11:25:13,508::resourceManager::939::ResourceManager.Owner::(releaseAl= l) =20 =20 Owner.releaseAll requests {} resources {} =20 =20 Thread-1249::DEBUG::2013-10-30 =20 =20 11:25:13,508::resourceManager::976::ResourceManager.Owner::(cancelAll= ) =20 =20 Owner.cancelAll requests {} =20 =20 Thread-1249::DEBUG::2013-10-30 =20 =20 11:25:13,508::task::974::TaskManager.Task::(_decref) =20 =20 Task=3D`8518162d-eb91-44aa-819a-354e05807cb9`::ref 0 aborting False =20 =20 Thread-1250::DEBUG::2013-10-30 =20 =20 11:25:13,510::BindingXMLRPC::177::vds::(wrapper) client [172.16.0.5] =20 =20 Thread-1250::DEBUG::2013-10-30 =20 =20 11:25:13,510::task::579::TaskManager.Task::(_updateState) =20 =20 Task=3D`221b537a-2c1b-418f-93ff-bf77d4029097`::moving from state init= -> state =20 =20 preparing =20 =20 Thread-1250:: INFO::2013-10-30 11:25:13,511::logUtils::44::dispatcher::(wrapper) Run and protect: =20 =20 getStoragePoolInfo(spUUID=3D'e3cb7694-47f7-4eac-9201-922e381a25dc', =20 =20 options=3DNone) =20 =20 Thread-1250::DEBUG::2013-10-30 =20 =20 11:25:13,511::resourceManager::197::ResourceManager.Request::(__init_= _) =20 =20 ResName=3D`Storage.e3cb7694-47f7-4eac-9201-922e381a25dc`ReqID=3D`42f3= 23ef-aa03-49e6-893f-0e4ff0764b6b`::Request =20 =20 was made in '/usr/share/vdsm/storage/hsm.py' line '2560' at =20 =20 'getStoragePoolInfo' =20 =20 Thread-1250::DEBUG::2013-10-30 =20 =20 11:25:13,511::resourceManager::541::ResourceManager::(registerResourc= e) =20 =20 Trying to register resource 'Storage.e3cb7694-47f7-4eac-9201-922e381a25dc' =20 =20 for lock type 'shared' =20 =20 Thread-1250::DEBUG::2013-10-30 =20 =20 11:25:13,511::resourceManager::600::ResourceManager::(registerResourc= e) =20 =20 Resource 'Storage.e3cb7694-47f7-4eac-9201-922e381a25dc' is free. Now locking =20 =20 as 'shared' (1 active user) =20 =20 Thread-1250::DEBUG::2013-10-30 =20 =20 11:25:13,511::resourceManager::237::ResourceManager.Request::(grant) =20 =20 ResName=3D`Storage.e3cb7694-47f7-4eac-9201-922e381a25dc`ReqID=3D`42f3= 23ef-aa03-49e6-893f-0e4ff0764b6b`::Granted =20 =20 request =20 =20 Thread-1250::DEBUG::2013-10-30 =20 =20 11:25:13,512::task::811::TaskManager.Task::(resourceAcquired) =20 =20 Task=3D`221b537a-2c1b-418f-93ff-bf77d4029097`::_resourcesAcquired: =20 =20 Storage.e3cb7694-47f7-4eac-9201-922e381a25dc (shared) =20 =20 Thread-1250::DEBUG::2013-10-30 =20 =20 11:25:13,512::task::974::TaskManager.Task::(_decref) =20 =20 Task=3D`221b537a-2c1b-418f-93ff-bf77d4029097`::ref 1 aborting False =20 =20 Thread-1250:: INFO::2013-10-30 11:25:13,517::logUtils::47::dispatcher::(wrapper) Run and protect: =20 =20 getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': =20 =20 '21e3d67f-fdec-4f87-b09e-53af994a6f87', 'name': 'GlusterSD', 'version= ': '3', =20 =20 'domains': =20 =20 '21e3d67f-fdec-4f87-b09e-53af994a6f87:Active,8e56a914-3395-48ad-ab4c-= c2ca7f9956b4:Active', =20 =20 'pool_status': 'connected', 'isoprefix': =20 =20 '/rhev/data-center/mnt/172.16.0.5:_home_iso2/8e56a914-3395-48ad-ab4c-= c2ca7f9956b4/images/11111111-1111-1111-1111-111111111111', =20 =20 'type': 'GLUSTERFS', 'master_ver': 1, 'lver': 3}, 'dominfo': =20 =20 {'21e3d67f-fdec-4f87-b09e-53af994a6f87': {'status': 'Active', 'diskfr= ee': =20 =20 '239969632256', 'alerts': [], 'version': 3, 'disktotal': '49212044083= 2'}, =20 =20 '8e56a914-3395-48ad-ab4c-c2ca7f9956b4': {'status': 'Active', 'diskfre= e': =20 =20 '201653747712', 'alerts': [], 'version': 0, 'disktotal': '246783410176'}}} =20 =20 Thread-1250::DEBUG::2013-10-30 =20 =20 11:25:13,517::task::1168::TaskManager.Task::(prepare) =20 =20 Task=3D`221b537a-2c1b-418f-93ff-bf77d4029097`::finished: {'info': {'spm_id': =20 =20 1, 'master_uuid': '21e3d67f-fdec-4f87-b09e-53af994a6f87', 'name': =20 =20 'GlusterSD', 'version': '3', 'domains': =20 =20 '21e3d67f-fdec-4f87-b09e-53af994a6f87:Active,8e56a914-3395-48ad-ab4c-= c2ca7f9956b4:Active', =20 =20 'pool_status': 'connected', 'isoprefix': =20 =20 '/rhev/data-center/mnt/172.16.0.5:_home_iso2/8e56a914-3395-48ad-ab4c-= c2ca7f9956b4/images/11111111-1111-1111-1111-111111111111', =20 =20 'type': 'GLUSTERFS', 'master_ver': 1, 'lver': 3}, 'dominfo': =20 =20 {'21e3d67f-fdec-4f87-b09e-53af994a6f87': {'status': 'Active', 'diskfr= ee': =20 =20 '239969632256', 'alerts': [], 'version': 3, 'disktotal': '49212044083= 2'}, =20 =20 '8e56a914-3395-48ad-ab4c-c2ca7f9956b4': {'status': 'Active', 'diskfre= e': =20 =20 '201653747712', 'alerts': [], 'version': 0, 'disktotal': '246783410176'}}} =20 =20 Thread-1250::DEBUG::2013-10-30 =20 =20 11:25:13,517::task::579::TaskManager.Task::(_updateState) =20 =20 Task=3D`221b537a-2c1b-418f-93ff-bf77d4029097`::moving from state prep= aring -> =20 =20 state finished =20 =20 Thread-1250::DEBUG::2013-10-30 =20 =20 11:25:13,517::resourceManager::939::ResourceManager.Owner::(releaseAl= l) =20 =20 Owner.releaseAll requests {} resources =20 =20 {'Storage.e3cb7694-47f7-4eac-9201-922e381a25dc': < ResourceRef =20 =20 'Storage.e3cb7694-47f7-4eac-9201-922e381a25dc', isValid: 'True' obj: =20 =20 'None'>} =20 =20 Thread-1250::DEBUG::2013-10-30 =20 =20 11:25:13,518::resourceManager::976::ResourceManager.Owner::(cancelAll= ) =20 =20 Owner.cancelAll requests {} =20 =20 Thread-1250::DEBUG::2013-10-30 =20 =20 11:25:13,518::resourceManager::615::ResourceManager::(releaseResource= ) =20 =20 Trying to release resource 'Storage.e3cb7694-47f7-4eac-9201-922e381a2= 5dc' =20 =20 Thread-1250::DEBUG::2013-10-30 =20 =20 11:25:13,518::resourceManager::634::ResourceManager::(releaseResource= ) =20 =20 Released resource 'Storage.e3cb7694-47f7-4eac-9201-922e381a25dc' (0 active =20 =20 users) =20 =20 Thread-1250::DEBUG::2013-10-30 =20 =20 11:25:13,518::resourceManager::640::ResourceManager::(releaseResource= ) =20 =20 Resource 'Storage.e3cb7694-47f7-4eac-9201-922e381a25dc' is free, find= ing out =20 =20 if anyone is waiting for it. =20 =20 Thread-1250::DEBUG::2013-10-30 =20 =20 11:25:13,518::resourceManager::648::ResourceManager::(releaseResource= ) No =20 =20 one is waiting for resource 'Storage.e3cb7694-47f7-4eac-9201-922e381a25dc', =20 =20 Clearing records. =20 =20 Thread-1250::DEBUG::2013-10-30 =20 =20 11:25:13,518::task::974::TaskManager.Task::(_decref) =20 =20 Task=3D`221b537a-2c1b-418f-93ff-bf77d4029097`::ref 0 aborting False =20 =20 Thread-242::DEBUG::2013-10-30 =20 =20 11:25:15,046::fileSD::238::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd =20 =20 iflag=3Ddirect =20 =20 if=3D/rhev/data-center/mnt/glusterSD/172.16.0.100:vms/21e3d67f-fdec-4= f87-b09e-53af994a6f87/dom_md/metadata =20 =20 bs=3D4096 count=3D1' (cwd None) =20 =20 Thread-242::DEBUG::2013-10-30 =20 =20 11:25:15,051::fileSD::238::Storage.Misc.excCmd::(getReadDelay) SUCCES= S: =20 =20 <err> =3D '0+1 records in\n0+1 records out\n497 bytes (497 B) copied, =20 =20 0.00032077 s, 1.5 MB/s\n'; <rc> =3D 0 =20 =20 Thread-243::DEBUG::2013-10-30 =20 =20 11:25:17,777::fileSD::238::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd =20 =20 iflag=3Ddirect =20 =20 if=3D/rhev/data-center/mnt/172.16.0.5:_home_iso2/8e56a914-3395-48ad-a= b4c-c2ca7f9956b4/dom_md/metadata =20 =20 bs=3D4096 count=3D1' (cwd None) =20 =20 Thread-243::DEBUG::2013-10-30 =20 =20 11:25:17,780::fileSD::238::Storage.Misc.excCmd::(getReadDelay) SUCCES= S: =20 =20 <err> =3D '0+1 records in\n0+1 records out\n373 bytes (373 B) copied, =20 =20 9.9232e-05 s, 3.8 Thread-1239::DEBUG::2013-10-30 =20 =20 11:25:03,420::task::974::TaskManager.Task::(_decref) =20 =20 Task=3D`d891f3d3-070d-403f-9050-f10651a7fc47`::ref 0 aborting False =20 =20 Thread-242::DEBUG::2013-10-30 =20 =20 11:25:04,982::domainMonitor::178::Storage.DomainMonitorThread::(_moni= torDomain) =20 =20 Refreshing domain 21e3d67f-fdec-4f87-b09e-53af994a6f87 =20 =20 Thread-242::DEBUG::2013-10-30 =20 =20 11:25:04,992::fileSD::153::Storage.StorageDomain::(__init__) Reading domain =20 =20 in path =20 =20 /rhev/data-center/mnt/glusterSD/172.16.0.100:vms/21e3d67f-fdec-4f87-b= 09e-53af994a6f87 =20 =20 Thread-242::DEBUG::2013-10-30 =20 =20 11:25:04,994::persistentDict::192::Storage.PersistentDict::(__init__) =20 =20 Created a persistent dict with FileMetadataRW backend =20 =20 Thread-242::DEBUG::2013-10-30 =20 =20 11:25:05,005::persistentDict::234::Storage.PersistentDict::(refresh) = read =20 =20 lines (FileMetadataRW)=3D['CLASS=3DData', 'DESCRIPTION=3Dvms', =20 =20 'IOOPTIMEOUTSEC=3D10', 'LEASERETRIES=3D3', 'LEASETIMESEC=3D60', 'LOCK= POLICY=3D', =20 =20 'LOCKRENEWALINTERVALSEC=3D5', 'MASTER_VERSION=3D1', =20 =20 'POOL_DESCRIPTION=3DGlusterSD', =20 =20 'POOL_DOMAINS=3D21e3d67f-fdec-4f87-b09e-53af994a6f87:Active,8e56a914-= 3395-48ad-ab4c-c2ca7f9956b4:Active', =20 =20 'POOL_SPM_ID=3D1', 'POOL_SPM_LVER=3D3', =20 =20 'POOL_UUID=3De3cb7694-47f7-4eac-9201-922e381a25dc', =20 =20 'REMOTE_PATH=3D172.16.0.100:vms', 'ROLE=3DMaster', =20 =20 'SDUUID=3D21e3d67f-fdec-4f87-b09e-53af994a6f87', 'TYPE=3DGLUSTERFS', =20 =20 'VERSION=3D3', '_SHA_CKSUM=3D2d0dc3836063d45dd1d8046aaf00bce05c2455ea= '] =20 =20 Thread-242::DEBUG::2013-10-30 =20 =20 11:25:05,008::fileSD::535::Storage.StorageDomain::(imageGarbageCollec= tor) =20 =20 Removing remnants of deleted images [] =20 =20 Thread-242:: INFO::2013-10-30 11:25:05,008::sd::374::Storage.StorageDomain::(_registerResourceNames= paces) =20 =20 Resource namespace 21e3d67f-fdec-4f87-b09e-53af994a6f87_imageNS alrea= dy =20 =20 registered =20 =20 Thread-242:: INFO::2013-10-30 11:25:05,008::sd::382::Storage.StorageDomain::(_registerResourceNames= paces) =20 =20 Resource namespace 21e3d67f-fdec-4f87-b09e-53af994a6f87_volumeNS alre= ady =20 =20 registered =20 =20 Thread-242::DEBUG::2013-10-30 =20 =20 11:25:05,020::fileSD::238::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd =20 =20 iflag=3Ddirect =20 =20 if=3D/rhev/data-center/mnt/glusterSD/172.16.0.100:vms/21e3d67f-fdec-4= f87-b09e-53af994a6f87/dom_md/metadata =20 =20 bs=3D4096 count=3D1' (cwd None) =20 =20 Thread-242::DEBUG::2013-10-30 =20 =20 11:25:05,026::fileSD::238::Storage.Misc.excCmd::(getReadDelay) SUCCES= S: =20 =20 <err> =3D '0+1 records in\n0+1 records out\n497 bytes (497 B) copied, =20 =20 0.000280701 s, 1.8 MB/s\n'; <rc> =3D 0 =20 =20 Thread-243::DEBUG::2013-10-30 =20 =20 11:25:07,721::domainMonitor::178::Storage.DomainMonitorThread::(_moni= torDomain) =20 =20 Refreshing domain 8e56a914-3395-48ad-ab4c-c2ca7f9956b4 =20 =20 Thread-243::DEBUG::2013-10-30 =20 =20 11:25:07,730::fileSD::153::Storage.StorageDomain::(__init__) Reading domain =20 =20 in path =20 =20 /rhev/data-center/mnt/172.16.0.5:_home_iso2/8e56a914-3395-48ad-ab4c-c= 2ca7f9956b4 =20 =20 Thread-243::DEBUG::2013-10-30 =20 =20 11:25:07,731::persistentDict::192::Storage.PersistentDict::(__init__) =20 =20 Created a persistent dict with FileMetadataRW backend =20 =20 Thread-243::DEBUG::2013-10-30 =20 =20 11:25:07,740::persistentDict::234::Storage.PersistentDict::(refresh) = read =20 =20 lines (FileMetadataRW)=3D['CLASS=3DIso', 'DESCRIPTION=3DISO', 'IOOPTIMEOUTSEC=3D1', =20 =20 'LEASERETRIES=3D3', 'LEASETIMESEC=3D5', 'LOCKPOLICY=3D', =20 =20 'LOCKRENEWALINTERVALSEC=3D5', 'MASTER_VERSION=3D0', =20 =20 'POOL_UUID=3D01b79582-75e3-436d-bade-db653207620b,e3cb7694-47f7-4eac-= 9201-922e381a25dc', =20 =20 'REMOTE_PATH=3D172.16.0.5:/home/iso2', 'ROLE=3DRegular', =20 =20 'SDUUID=3D8e56a914-3395-48ad-ab4c-c2ca7f9956b4', 'TYPE=3DNFS', 'VERSI= ON=3D0', =20 =20 '_SHA_CKSUM=3Db0d102325f279bb8efa68c594cbace0b11c66783'] =20 =20 Thread-243::DEBUG::2013-10-30 =20 =20 11:25:07,741::fileSD::535::Storage.StorageDomain::(imageGarbageCollec= tor) =20 =20 Removing remnants of deleted images [] =20 =20 Thread-243:: INFO::2013-10-30 11:25:07,741::sd::374::Storage.StorageDomain::(_registerResourceNames= paces) =20 =20 Resource namespace 8e56a914-3395-48ad-ab4c-c2ca7f9956b4_imageNS alrea= dy =20 =20 registered =20 =20 Thread-243:: INFO::2013-10-30 11:25:07,741::sd::382::Storage.StorageDomain::(_registerResourceNames= paces) =20 =20 Resource namespace 8e56a914-3395-48ad-ab4c-c2ca7f9956b4_volumeNS alre= ady =20 =20 registered =20 =20 Thread-243::DEBUG::2013-10-30 =20 =20 11:25:07,757::fileSD::238::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd =20 =20 iflag=3Ddirect =20 =20 if=3D/rhev/data-center/mnt/172.16.0.5:_home_iso2/8e56a914-3395-48ad-a= b4c-c2ca7f9956b4/dom_md/metadata =20 =20 bs=3D4096 count=3D1' (cwd None) =20 =20 Thread-243::DEBUG::2013-10-30 =20 =20 11:25:07,760::fileSD::238::Storage.Misc.excCmd::(getReadDelay) SUCCES= S: =20 =20 <err> =3D '0+1 records in\n0+1 records out\n373 bytes (373 B) copied, =20 =20 0.000128829 s, 2.9 MB/s\n'; <rc> =3D 0 =20 =20 Thread-1246::DEBUG::2013-10-30 =20 =20 11:25:09,944::task::579::TaskManager.Task::(_updateState) =20 =20 Task=3D`c064522b-6fe7-4cb2-b85d-ad1f8185919a`::moving from state init= -> state =20 =20 preparing =20 =20 Thread-1246:: INFO::2013-10-30 11:25:09,944::logUtils::44::dispatcher::(wrapper) Run and protect: =20 =20 repoStats(options=3DNone) =20 =20 Thread-1246:: INFO::2013-10-30 11:25:09,945::logUtils::47::dispatcher::(wrapper) Run and protect: =20 =20 repoStats, Return response: {'21e3d67f-fdec-4f87-b09e-53af994a6f87': =20 =20 {'delay': '0.000280701', 'lastCheck': '4.9', 'code': 0, 'valid': True= , =20 =20 'version': 3}, '8e56a914-3395-48ad-ab4c-c2ca7f9956b4': {'delay': =20 =20 '0.000128829', 'lastCheck': '2.2', 'code': 0, 'valid': True, 'version= ': 0}} =20 =20 Thread-1246::DEBUG::2013-10-30 =20 =20 11:25:09,945::task::1168::TaskManager.Task::(prepare) =20 =20 Task=3D`c064522b-6fe7-4cb2-b85d-ad1f8185919a`::finished: =20 =20 {'21e3d67f-fdec-4f87-b09e-53af994a6f87': {'delay': '0.000280701', =20 =20 'lastCheck': '4.9', 'code': 0, 'valid': True, 'version': 3}, =20 =20 '8e56a914-3395-48ad-ab4c-c2ca7f9956b4': {'delay': '0.000128829', =20 =20 'lastCheck': '2.2', 'code': 0, 'valid': True, 'version': 0}} =20 =20 Thread-1246::DEBUG::2013-10-30 =20 =20 11:25:09,945::task::579::TaskManager.Task::(_updateState) =20 =20 Task=3D`c064522b-6fe7-4cb2-b85d-ad1f8185919a`::moving from state prep= aring -> =20 =20 state finished =20 =20 Thread-1246::DEBUG::2013-10-30 =20 =20 11:25:09,945::resourceManager::939::ResourceManager.Owner::(releaseAl= l) =20 =20 Owner.releaseAll requests {} resources {} =20 =20 Thread-1246::DEBUG::2013-10-30 =20 =20 11:25:09,945::resourceManager::976::ResourceManager.Owner::(cancelAll= ) =20 =20 Owner.cancelAll requests {} =20 =20 Thread-1246::DEBUG::2013-10-30 =20 =20 11:25:09,945::task::974::TaskManager.Task::(_decref) =20 =20 Task=3D`c064522b-6fe7-4cb2-b85d-ad1f8185919a`::ref 0 aborting False =20 =20 Thread-1249::DEBUG::2013-10-30 =20 =20 11:25:13,507::BindingXMLRPC::177::vds::(wrapper) client [172.16.0.5] =20 =20 Thread-1249::DEBUG::2013-10-30 =20 =20 11:25:13,507::task::579::TaskManager.Task::(_updateState) =20 =20 Task=3D`8518162d-eb91-44aa-819a-354e05807cb9`::moving from state init= -> state =20 =20 preparing =20 =20 Thread-1249:: INFO::2013-10-30 11:25:13,507::logUtils::44::dispatcher::(wrapper) Run and protect: =20 =20 getSpmStatus(spUUID=3D'e3cb7694-47f7-4eac-9201-922e381a25dc', options= =3DNone) =20 =20 Thread-1249:: INFO::2013-10-30 11:25:13,508::logUtils::47::dispatcher::(wrapper) Run and protect: =20 =20 getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', =20 =20 'spmLver': 3}} =20 =20 Thread-1249::DEBUG::2013-10-30 =20 =20 11:25:13,508::task::1168::TaskManager.Task::(prepare) =20 =20 Task=3D`8518162d-eb91-44aa-819a-354e05807cb9`::finished: {'spm_st': {'spmId': =20 =20 1, 'spmStatus': 'SPM', 'spmLver': 3}} =20 =20 Thread-1249::DEBUG::2013-10-30 =20 =20 11:25:13,508::task::579::TaskManager.Task::(_updateState) =20 =20 Task=3D`8518162d-eb91-44aa-819a-354e05807cb9`::moving from state prep= aring -> =20 =20 state finished =20 =20 Thread-1249::DEBUG::2013-10-30 =20 =20 11:25:13,508::resourceManager::939::ResourceManager.Owner::(releaseAl= l) =20 =20 Owner.releaseAll requests {} resources {} =20 =20 Thread-1249::DEBUG::2013-10-30 =20 =20 11:25:13,508::resourceManager::976::ResourceManager.Owner::(cancelAll= ) =20 =20 Owner.cancelAll requests {} =20 =20 Thread-1249::DEBUG::2013-10-30 =20 =20 11:25:13,508::task::974::TaskManager.Task::(_decref) =20 =20 Task=3D`8518162d-eb91-44aa-819a-354e05807cb9`::ref 0 aborting False =20 =20 Thread-1250::DEBUG::2013-10-30 =20 =20 11:25:13,510::BindingXMLRPC::177::vds::(wrapper) client [172.16.0.5] =20 =20 Thread-1250::DEBUG::2013-10-30 =20 =20 11:25:13,510::task::579::TaskManager.Task::(_updateState) =20 =20 Task=3D`221b537a-2c1b-418f-93ff-bf77d4029097`::moving from state init= -> state =20 =20 preparing =20 =20 Thread-1250:: INFO::2013-10-30 11:25:13,511::logUtils::44::dispatcher::(wrapper) Run and protect: =20 =20 getStoragePoolInfo(spUUID=3D'e3cb7694-47f7-4eac-9201-922e381a25dc', =20 =20 options=3DNone) =20 =20 Thread-1250::DEBUG::2013-10-30 =20 =20 11:25:13,511::resourceManager::197::ResourceManager.Request::(__init_= _) =20 =20 ResName=3D`Storage.e3cb7694-47f7-4eac-9201-922e381a25dc`ReqID=3D`42f3= 23ef-aa03-49e6-893f-0e4ff0764b6b`::Request =20 =20 was made in '/usr/share/vdsm/storage/hsm.py' line '2560' at =20 =20 'getStoragePoolInfo' =20 =20 Thread-1250::DEBUG::2013-10-30 =20 =20 11:25:13,511::resourceManager::541::ResourceManager::(registerResourc= e) =20 =20 Trying to register resource 'Storage.e3cb7694-47f7-4eac-9201-922e381a25dc' =20 =20 for lock type 'shared' =20 =20 Thread-1250::DEBUG::2013-10-30 =20 =20 11:25:13,511::resourceManager::600::ResourceManager::(registerResourc= e) =20 =20 Resource 'Storage.e3cb7694-47f7-4eac-9201-922e381a25dc' is free. Now locking =20 =20 as 'shared' (1 active user) =20 =20 Thread-1250::DEBUG::2013-10-30 =20 =20 11:25:13,511::resourceManager::237::ResourceManager.Request::(grant) =20 =20 ResName=3D`Storage.e3cb7694-47f7-4eac-9201-922e381a25dc`ReqID=3D`42f3= 23ef-aa03-49e6-893f-0e4ff0764b6b`::Granted =20 =20 request =20 =20 Thread-1250::DEBUG::2013-10-30 =20 =20 11:25:13,512::task::811::TaskManager.Task::(resourceAcquired) =20 =20 Task=3D`221b537a-2c1b-418f-93ff-bf77d4029097`::_resourcesAcquired: =20 =20 Storage.e3cb7694-47f7-4eac-9201-922e381a25dc (shared) =20 =20 Thread-1250::DEBUG::2013-10-30 =20 =20 11:25:13,512::task::974::TaskManager.Task::(_decref) =20 =20 Task=3D`221b537a-2c1b-418f-93ff-bf77d4029097`::ref 1 aborting False =20 =20 Thread-1250:: INFO::2013-10-30 11:25:13,517::logUtils::47::dispatcher::(wrapper) Run and protect: =20 =20 getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': =20 =20 '21e3d67f-fdec-4f87-b09e-53af994a6f87', 'name': 'GlusterSD', 'version= ': '3', =20 =20 'domains': =20 =20 '21e3d67f-fdec-4f87-b09e-53af994a6f87:Active,8e56a914-3395-48ad-ab4c-= c2ca7f9956b4:Active', =20 =20 'pool_status': 'connected', 'isoprefix': =20 =20 '/rhev/data-center/mnt/172.16.0.5:_home_iso2/8e56a914-3395-48ad-ab4c-= c2ca7f9956b4/images/11111111-1111-1111-1111-111111111111', =20 =20 'type': 'GLUSTERFS', 'master_ver': 1, 'lver': 3}, 'dominfo': =20 =20 {'21e3d67f-fdec-4f87-b09e-53af994a6f87': {'status': 'Active', 'diskfr= ee': =20 =20 '239969632256', 'alerts': [], 'version': 3, 'disktotal': '49212044083= 2'}, =20 =20 '8e56a914-3395-48ad-ab4c-c2ca7f9956b4': {'status': 'Active', 'diskfre= e': =20 =20 '201653747712', 'alerts': [], 'version': 0, 'disktotal': '246783410176'}}} =20 =20 Thread-1250::DEBUG::2013-10-30 =20 =20 11:25:13,517::task::1168::TaskManager.Task::(prepare) =20 =20 Task=3D`221b537a-2c1b-418f-93ff-bf77d4029097`::finished: {'info': {'spm_id': =20 =20 1, 'master_uuid': '21e3d67f-fdec-4f87-b09e-53af994a6f87', 'name': =20 =20 'GlusterSD', 'version': '3', 'domains': =20 =20 '21e3d67f-fdec-4f87-b09e-53af994a6f87:Active,8e56a914-3395-48ad-ab4c-= c2ca7f9956b4:Active', =20 =20 'pool_status': 'connected', 'isoprefix': =20 =20 '/rhev/data-center/mnt/172.16.0.5:_home_iso2/8e56a914-3395-48ad-ab4c-= c2ca7f9956b4/images/11111111-1111-1111-1111-111111111111', =20 =20 'type': 'GLUSTERFS', 'master_ver': 1, 'lver': 3}, 'dominfo': =20 =20 {'21e3d67f-fdec-4f87-b09e-53af994a6f87': {'status': 'Active', 'diskfr= ee': =20 =20 '239969632256', 'alerts': [], 'version': 3, 'disktotal': '49212044083= 2'}, =20 =20 '8e56a914-3395-48ad-ab4c-c2ca7f9956b4': {'status': 'Active', 'diskfre= e': =20 =20 '201653747712', 'alerts': [], 'version': 0, 'disktotal': '246783410176'}}} =20 =20 Thread-1250::DEBUG::2013-10-30 =20 =20 11:25:13,517::task::579::TaskManager.Task::(_updateState) =20 =20 Task=3D`221b537a-2c1b-418f-93ff-bf77d4029097`::moving from state prep= aring -> =20 =20 state finished =20 =20 Thread-1250::DEBUG::2013-10-30 =20 =20 11:25:13,517::resourceManager::939::ResourceManager.Owner::(releaseAl= l) =20 =20 Owner.releaseAll requests {} resources =20 =20 {'Storage.e3cb7694-47f7-4eac-9201-922e381a25dc': < ResourceRef =20 =20 'Storage.e3cb7694-47f7-4eac-9201-922e381a25dc', isValid: 'True' obj: =20 =20 'None'>} =20 =20 Thread-1250::DEBUG::2013-10-30 =20 =20 11:25:13,518::resourceManager::976::ResourceManager.Owner::(cancelAll= ) =20 =20 Owner.cancelAll requests {} =20 =20 Thread-1250::DEBUG::2013-10-30 =20 =20 11:25:13,518::resourceManager::615::ResourceManager::(releaseResource= ) =20 =20 Trying to release resource 'Storage.e3cb7694-47f7-4eac-9201-922e381a2= 5dc' =20 =20 Thread-1250::DEBUG::2013-10-30 =20 =20 11:25:13,518::resourceManager::634::ResourceManager::(releaseResource= ) =20 =20 Released resource 'Storage.e3cb7694-47f7-4eac-9201-922e381a25dc' (0 active =20 =20 users) =20 =20 Thread-1250::DEBUG::2013-10-30 =20 =20 11:25:13,518::resourceManager::640::ResourceManager::(releaseResource= ) =20 =20 Resource 'Storage.e3cb7694-47f7-4eac-9201-922e381a25dc' is free, find= ing out =20 =20 if anyone is waiting for it. =20 =20 Thread-1250::DEBUG::2013-10-30 =20 =20 11:25:13,518::resourceManager::648::ResourceManager::(releaseResource= ) No =20 =20 one is waiting for resource 'Storage.e3cb7694-47f7-4eac-9201-922e381a25dc', =20 =20 Clearing records. =20 =20 Thread-1250::DEBUG::2013-10-30 =20 =20 11:25:13,518::task::974::TaskManager.Task::(_decref) =20 =20 Task=3D`221b537a-2c1b-418f-93ff-bf77d4029097`::ref 0 aborting False =20 =20 Thread-242::DEBUG::2013-10-30 =20 =20 11:25:15,046::fileSD::238::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd =20 =20 iflag=3Ddirect =20 =20 if=3D/rhev/data-center/mnt/glusterSD/172.16.0.100:vms/21e3d67f-fdec-4= f87-b09e-53af994a6f87/dom_md/metadata =20 =20 bs=3D4096 count=3D1' (cwd None) =20 =20 Thread-242::DEBUG::2013-10-30 =20 =20 11:25:15,051::fileSD::238::Storage.Misc.excCmd::(getReadDelay) SUCCES= S: =20 =20 <err> =3D '0+1 records in\n0+1 records out\n497 bytes (497 B) copied, =20 =20 0.00032077 s, 1.5 MB/s\n'; <rc> =3D 0 =20 =20 Thread-243::DEBUG::2013-10-30 =20 =20 11:25:17,777::fileSD::238::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd =20 =20 iflag=3Ddirect =20 =20 if=3D/rhev/data-center/mnt/172.16.0.5:_home_iso2/8e56a914-3395-48ad-a= b4c-c2ca7f9956b4/dom_md/metadata =20 =20 bs=3D4096 count=3D1' (cwd None) =20 =20 Thread-243::DEBUG::2013-10-30 =20 =20 11:25:17,780::fileSD::238::Storage.Misc.excCmd::(getReadDelay) SUCCES= S: =20 =20 <err> =3D '0+1 records in\n0+1 records out\n373 bytes (373 B) copied, =20 =20 9.9232e-05 s, 3.8 MB/s\n'; <rc> =3D 0 =20 =20
engine.log =20 =20
2013-10-30 11:17:47,729 INFO [org.ovirt.engine.core.bll.RunVmOnceComm= and] =20 =20 (ajp--127.0.0.1-8702-6) Running command: RunVmOnceCommand internal: false. =20 =20 Entities affected : ID: 200dfb05-461e-49d9-95a2-c0a7c7ced669 Type: VM =20 =20 2013-10-30 11:17:47,743 INFO =20 =20 [org.ovirt.engine.core.vdsbroker.CreateVmVDSCommand] (ajp--127.0.0.1-8702-6) =20 =20 START, CreateVmVDSCommand(HostName =3D Hypervisor, HostId =3D =20 =20 da764821-0650-40f0-b7cf-038766fbd2ca, =20 =20 vmId=3D200dfb05-461e-49d9-95a2-c0a7c7ced669, vm=3DVM [CentOS_30]), lo= g id: =20 =20 638a3a0e =20 =20 2013-10-30 11:17:47,765 INFO =20 =20 [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] =20 =20 (ajp--127.0.0.1-8702-6) START, CreateVDSCommand(HostName =3D Hypervis= or, =20 =20 HostId =3D da764821-0650-40f0-b7cf-038766fbd2ca, =20 =20 vmId=3D200dfb05-461e-49d9-95a2-c0a7c7ced669, vm=3DVM [CentOS_30]), lo= g id: =20 =20 297dbca2 =20 =20 2013-10-30 11:17:47,784 INFO =20 =20 [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] =20 =20 (ajp--127.0.0.1-8702-6) =20 =20 org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand =20 =20 spiceSslCipherSuite=3DDEFAULT,memSize=3D2048,kvmEnable=3Dtrue,smp=3D1= ,vmType=3Dkvm,emulatedMachine=3Dpc-1.0,keyboardLayout=3Den-us,memGuaranteed= Size=3D1365,pitReinjection=3Dfalse,nice=3D0,display=3Dqxl,smartcardEnable= =3Dfalse,smpCoresPerSocket=3D1,spiceSecureChannels=3Dsmain,sinputs,scursor,= splayback,srecord,sdisplay,susbredir,ssmartcard,timeOffset=3D0,transparentH= ugePages=3Dtrue,vmId=3D200dfb05-461e-49d9-95a2-c0a7c7ced669,devices=3D[Ljav= a.util.HashMap;@f3eee3e,acpiEnable=3Dtrue,vmName=3DCentOS_30,cpuType=3DWest= mere,custom=3D{} =20 =20 2013-10-30 11:17:47,785 INFO =20 =20 [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] =20 =20 (ajp--127.0.0.1-8702-6) FINISH, CreateVDSCommand, log id: 297dbca2 =20 =20 2013-10-30 11:17:47,786 INFO =20 =20 [org.ovirt.engine.core.vdsbroker.CreateVmVDSCommand] (ajp--127.0.0.1-8702-6) =20 =20 FINISH, CreateVmVDSCommand, return: WaitForLaunch, log id: 638a3a0e =20 =20 2013-10-30 11:17:47,812 INFO =20 =20 [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector= ] =20 =20 (ajp--127.0.0.1-8702-6) Correlation ID: 4f8bc4f9, Job ID: =20 =20 74a77fc0-7e83-44c0-b3d7-334eb38612b4, Call Stack: null, Custom Event = ID: -1, =20 =20 Message: VM CentOS_30 was started by admin@internal (Host: Hypervisor= ). =20 =20 2013-10-30 11:17:51,115 INFO =20 =20 [org.ovirt.engine.core.vdsbroker.vdsbroker.FullListVdsCommand] =20 =20 (DefaultQuartzScheduler_Worker-37) START, FullListVdsCommand(HostName= =3D =20 =20 Hypervisor, HostId =3D da764821-0650-40f0-b7cf-038766fbd2ca, =20 =20 vds=3DHost[Hypervisor], vmIds=3D[200dfb05-461e-49d9-95a2-c0a7c7ced669= ]), log id: =20 =20 546bd3e2 =20 =20 2013-10-30 11:17:51,119 INFO =20 =20 [org.ovirt.engine.core.vdsbroker.vdsbroker.FullListVdsCommand] =20 =20 (DefaultQuartzScheduler_Worker-37) FINISH, FullListVdsCommand, return= : =20 =20 [Ljava.util.HashMap;@318a7164, log id: 546bd3e2 =20 =20 2013-10-30 11:17:51,121 INFO =20 =20 [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] =20 =20 (DefaultQuartzScheduler_Worker-37) Received a scsi Device without an address =20 =20 when processing VM 200dfb05-461e-49d9-95a2-c0a7c7ced669 devices, skip= ping =20 =20 device: {model=3Dvirtio-scsi, device=3Dscsi, type=3Dcontroller} =20 =20 2013-10-30 11:17:51,121 INFO =20 =20 [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] =20 =20 (DefaultQuartzScheduler_Worker-37) Received a cdrom Device without an =20 =20 address when processing VM 200dfb05-461e-49d9-95a2-c0a7c7ced669 devic= es, =20 =20 skipping device: {shared=3Dfalse, bootOrder=3D1, iface=3Dide, index= =3D2, =20 =20 specParams=3D{}, device=3Dcdrom, =20 =20 path=3D/rhev/data-center/mnt/172.16.0.5:_home_iso2/8e56a914-3395-48ad= -ab4c-c2ca7f9956b4/images/11111111-1111-1111-1111-111111111111/CentOS-6.4-x= 86_64-bin-DVD1.iso, =20 =20 type=3Ddisk, readonly=3Dtrue, deviceId=3De29c7ac7-f872-43e3-90e2-cb22= 05c0203f} =20 =20 2013-10-30 11:17:51,122 INFO =20 =20 [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] =20 =20 (DefaultQuartzScheduler_Worker-37) Received a disk Device without an address =20 =20 when processing VM 200dfb05-461e-49d9-95a2-c0a7c7ced669 devices, skip= ping =20 =20 device: {shared=3Dfalse, volumeID=3D202adc86-7857-40eb-8ca6-7cec3ef0d= 2d6, =20 =20 index=3D0, propagateErrors=3Doff, format=3Draw, type=3Ddisk, truesize= =3D4096, =20 =20 reqsize=3D0, bootOrder=3D2, iface=3Dvirtio, =20 =20 volumeChain=3D[Ljava.lang.Object;@8741843, =20 =20 imageID=3Db73a79fe-401b-434c-b023-6de4c3eb100d, =20 =20 domainID=3D21e3d67f-fdec-4f87-b09e-53af994a6f87, specParams=3D{}, =20 =20 optional=3Dfalse, volumeInfo=3D{volfileServer=3D172.16.0.100, volPort= =3D0, =20 =20 protocol=3Dgluster, volTransport=3Dtcp, =20 =20 path=3Dvms/21e3d67f-fdec-4f87-b09e-53af994a6f87/images/b73a79fe-401b-= 434c-b023-6de4c3eb100d/202adc86-7857-40eb-8ca6-7cec3ef0d2d6, =20 =20 volType=3Dnetwork}, =20 =20 path=3D/rhev/data-center/e3cb7694-47f7-4eac-9201-922e381a25dc/21e3d67= f-fdec-4f87-b09e-53af994a6f87/images/b73a79fe-401b-434c-b023-6de4c3eb100d/2= 02adc86-7857-40eb-8ca6-7cec3ef0d2d6, =20 =20 device=3Ddisk, poolID=3De3cb7694-47f7-4eac-9201-922e381a25dc, readonl= y=3Dfalse, =20 =20 deviceId=3Db73a79fe-401b-434c-b023-6de4c3eb100d, apparentsize=3D32212= 254720} =20 =20 2013-10-30 11:17:51,123 INFO =20 =20 [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] =20 =20 (DefaultQuartzScheduler_Worker-37) Received a memballoon Device witho= ut an =20 =20 address when processing VM 200dfb05-461e-49d9-95a2-c0a7c7ced669 devic= es, =20 =20 skipping device: {specParams=3D{model=3Dvirtio}, target=3D2097152, =20 =20 device=3Dmemballoon, type=3Dballoon, =20 =20 deviceId=3Db61b058d-cdfe-4d7c-8e6c-1bfd631cb26c} =20 =20
_______________________________________________ =20 =20 Users mailing list Users@ovirt.org http://lists.ovirt.org/mailman/listinfo/users =20 =20
participants (2)
-
Alessandro Bianchi -
Omer Frenkel