- Users - oVirt List Archives

[Users] What is the best way to debug a VDSM hook?
by Robert Middleswarth 26 Jun '12

26 Jun '12

I installed the hook smbios but it doesn't seem to be working. I was told earlier I needed to create a custom property to pass the data but that doesn't seem to be working. Not sure what I am doing wrong. I am looking for debugging hints on how to show what is being passed to the hook to confirm it is grabbing the correct info and what is being passed back to vdsm? http://gerrit.ovirt.org/gitweb?p=vdsm.git;a=tree;f=vdsm_hooks/smbios;h=c61c… Thanks Robert

2 7

[Users] Two updates from the oVirt team
by Ofer Schreiber 26 Jun '12

26 Jun '12

Hey everyone, There are two updates I'd like to share with you: 1. oVirt 3.1 release date has been delayed to the 9th of July. As you all know, We're in the middle of creating a new build of oVirt. With your help, we found multiple issues which we consider as release blockers. Some of these issues require a few days to be solved properly, and as a result, we had to delay the general availability of oVirt. 2. New ovirt-engine rpms are available for download at http://ovirt.org/releases/beta/fedora/17 This build contain multiple bug fixes, as well as a new versioning schema, which will ensure future updates will be done correctly. Please note, that due to the new versions, we don't support in-beta upgrade. please make sure you clean up you environment (using engine-cleanup, and yum remove) before installing the new rpms (version 3.1.0-0.1.20120620git6ef9f8.fc17) New VDSM rpms should be available in the beginning of next week). Regards, -- Ofer Schreiber oVirt Release Manager

1 1

[Users] oVirt 3.1 -- GlusterFS 3.3
by Nathan Stratton 26 Jun '12

26 Jun '12

Steps: 1) Installed ovirt-engine, configured Cluster for GlusterFS 2) Installed 8 ovirt 3.1 nodes 3) Joined all 8 notes with ovirt-engine (all up and happy) 4) Manually added all 8 peers for GlusterFS on hosts (all peers happy) 5) Create Volume errors: 2012-06-25 16:44:42,412 WARN [org.ovirt.engine.core.dal.job.ExecutionMessageDirector] (ajp--0.0.0.0-8009-4) [6c02c1f5] The message key CreateGlusterVolume is missing from bundles/ExecutionMessages 2012-06-25 16:44:42,483 INFO [org.ovirt.engine.core.bll.gluster.CreateGlusterVolumeCommand] (ajp--0.0.0.0-8009-4) [6c02c1f5] Running command: CreateGlusterVolumeCommand internal: false. Entities affected : ID: 99408929-82cf-4dc7-a532-9d998063fa95 Type: VdsGroups 2012-06-25 16:44:42,486 INFO [org.ovirt.engine.core.vdsbroker.gluster.CreateGlusterVolumeVDSCommand] (ajp--0.0.0.0-8009-4) [6c02c1f5] START, CreateGlusterVolumeVDSCommand(vdsId = 8324ff12-bf1c-11e1-b235-43d3f71a81d8), log id: 15757d4c 2012-06-25 16:44:42,593 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase] (ajp--0.0.0.0-8009-4) [6c02c1f5] Failed in CreateGlusterVolumeVDS method 2012-06-25 16:44:42,594 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase] (ajp--0.0.0.0-8009-4) [6c02c1f5] Error code unexpected and error message VDSGenericException: VDSErrorException: Failed to CreateGlusterVolumeVDS, error = Unexpected exception 2012-06-25 16:44:42,594 ERROR [org.ovirt.engine.core.vdsbroker.VDSCommandBase] (ajp--0.0.0.0-8009-4) [6c02c1f5] Command CreateGlusterVolumeVDS execution failed. Exception: VDSErrorException: VDSGenericException: VDSErrorException: Failed to CreateGlusterVolumeVDS, error = Unexpected exception 2012-06-25 16:44:42,595 INFO [org.ovirt.engine.core.vdsbroker.gluster.CreateGlusterVolumeVDSCommand] (ajp--0.0.0.0-8009-4) [6c02c1f5] FINISH, CreateGlusterVolumeVDSCommand, log id: 15757d4c 2012-06-25 16:44:42,596 ERROR [org.ovirt.engine.core.bll.gluster.CreateGlusterVolumeCommand] (ajp--0.0.0.0-8009-4) [6c02c1f5] Command org.ovirt.engine.core.bll.gluster.CreateGlusterVolumeCommand throw Vdc Bll exception. With error message VdcBLLException: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorException: VDSGenericException: VDSErrorException: Failed to CreateGlusterVolumeVDS, error = Unexpected exception ><> Nathan Stratton nathan at robotics.net http://www.robotics.net

3 14

[Users] Unable to add iSCSI storage domain - 3.1 beta
by Trey Dockendorf 25 Jun '12

25 Jun '12

I'm attempting to add iSCSI storage to a data center via web interface, and while I"m able to see the target ISCSI device and login, clicking the "OK" button doesn't submit the storage selection. I noticed from looking at the oVirt manual that somewhere in this interface I have to select the LUN. However once logged into the target I never see LUNs to select. I've attached two screenshots that show the UI and what could be errors in how it's being displayed. I also attached logs from vdsm host and engine that were captured while attempting to add the storage domain. After logging into the iSCSI target via web interface, this is the output on target host, showing that my ovirt node (10.20.1.240) is connected. # tgtadm --lld iscsi --op show --mode target Target 1: iqn.2012-06.edu.tamu.dc-store:lv_kvm_pool System information: Driver: iscsi node dc-store0.tamu.edu State: ready I_T nexus information: I_T nexus: 3 Initiator: iqn.1994-05.com.redhat:ad499aa5f37e Connection: 0 IP Address: 10.20.1.240 LUN information: LUN: 0 Type: controller SCSI ID: IET 00010000 SCSI SN: beaf10 Size: 0 MB, Block size: 1 Online: Yes Removable media: No Readonly: No Backing store type: null Backing store path: None Backing store flags: LUN: 1 Type: disk SCSI ID: p_lu_coraid23_lu SCSI SN: (stdin)= Size: 4398047 MB, Block size: 512 Online: Yes Removable media: No Readonly: No Backing store type: rdwr Backing store path: /dev/vg_coraid23/lv_kvm_pool Backing store flags: Account information: ACL information: ALL Based on some archived emails I've included previously mentioned outputs that may help >From the ovirt node: # iscsiadm -m discovery -p 10.20.1.250 -t sendtargets --login 10.20.1.250:3260,1 iqn.2012-06.edu.tamu.dc-store:lv_kvm_pool Logging in to [iface: default, target: iqn.2012-06.edu.tamu.dc-store:lv_kvm_pool, portal: 10.20.1.250,3260] (multiple) Login to [iface: default, target: iqn.2012-06.edu.tamu.dc-store:lv_kvm_pool, portal: 10.20.1.250,3260] successful. # multipath -r Jun 25 14:19:22 | 3600508e0000000004ecf45ecb0c2ec0a: ignoring map reload: 1p_lu_coraid23_lu undef IET,VIRTUAL-DISK size=4.0T features='0' hwhandler='0' wp=undef `-+- policy='round-robin 0' prio=1 status=undef `- 8:0:0:1 sdc 8:32 active ready running # iscsiadm -m session tcp: [4] 10.20.1.250:3260,1 iqn.2012-06.edu.tamu.dc-store:lv_kvm_pool # vdsClient -s 0 getDeviceList [{'GUID': '1p_lu_coraid23_lu', 'capacity': '4398046511104', 'devtype': 'iSCSI', 'fwrev': '0001', 'logicalblocksize': '512', 'partitioned': False, 'pathlist': [{'connection': '10.20.1.250', 'initiatorname': 'default', 'iqn': 'iqn.2012-06.edu.tamu.dc-store:lv_kvm_pool', 'port': '3260', 'portal': '1'}], 'pathstatus': [{'lun': '1', 'physdev': 'sdc', 'state': 'active', 'type': 'iSCSI'}], 'physicalblocksize': '512', 'productID': 'VIRTUAL-DISK', 'pvUUID': '7MHtfm-352q-zWrT-KfU8-sJ1l-e4rP-aKsuhu', 'serial': 'SIET_VIRTUAL-DISK', 'vendorID': 'IET', 'vgUUID': 'YCso68-YCo8-w817-I5Nf-mFx3-aoPe-LWkYco'}] # vgs -o+pv_name VG #PV #LV #SN Attr VSize VFree PV f18b2342-4713-4319-a878-3025b38556a4 1 6 0 wz--n- 4.00t 4.00t /dev/mapper/1p_lu_coraid23_lu vg_dc-kvm0 1 2 0 wz--n- 67.50g 0 /dev/sda2 Thanks - Trey

1 0

[Users] Vdsmd is respawning trying to sample NICs
by jose garcia 25 Jun '12

25 Jun '12

Good monday morning, Installed Fedora 17 and tried to install the node to a 3.1 engine. I'm getting an VDS Network exception in the engine side: in /var/log/ovirt-engine/engine: 2012-06-25 10:15:34,132 WARN [org.ovirt.engine.core.vdsbroker.VdsManager] (QuartzScheduler_Worker-96) ResourceManager::refreshVdsRunTimeInfo::Failed to refresh VDS , vds = 2e9929c6-bea6-11e1-bfdd-ff11f39c80eb : ovirt-node2.smb.eurotux.local, VDS Network Error, continuing. VDSNetworkException: 2012-06-25 10:15:36,143 ERROR [org.ovirt.engine.core.vdsbroker.VdsManager] (QuartzScheduler_Worker-20) VDS::handleNetworkException Server failed to respond, vds_id = 2e9929c6-bea6-11e1-bfdd-ff11f39c80eb, vds_name = ovirt-node2.smb.eurotux.local, error = VDSNetworkException: 2012-06-25 10:15:36,181 INFO [org.ovirt.engine.core.bll.VdsEventListener] (pool-3-thread-49) ResourceManager::vdsNotResponding entered for Host 2e9929c6-bea6-11e1-bfdd-ff11f39c80eb, 10.10.30.177 2012-06-25 10:15:36,214 ERROR [org.ovirt.engine.core.bll.VdsNotRespondingTreatmentCommand] (pool-3-thread-49) [1afd4b89] Failed to run Fence script on vds:ovirt-node2.smb.eurotux.local, VMs moved to UnKnown instead. While in the node, vdsmd does fail to sample nics: in /var/log/vdsm/vdsm.log: nf = netinfo.NetInfo() File "/usr/share/vdsm/netinfo.py", line 268, in __init__ _netinfo = get() File "/usr/share/vdsm/netinfo.py", line 220, in get for nic in nics() ]) KeyError: 'p36p1' MainThread::INFO::2012-06-25 10:45:09,110::vdsm::76::vds::(run) VDSM main thread ended. Waiting for 1 other threads... MainThread::INFO::2012-06-25 10:45:09,111::vdsm::79::vds::(run) <_MainThread(MainThread, started 140567823243072)> MainThread::INFO::2012-06-25 10:45:09,111::vdsm::79::vds::(run) <Thread(libvirtEventLoop, started daemon 140567752681216)> in /etc/var/log/messages there is a lot of vdsmd died too quickly: Jun 25 10:45:08 ovirt-node2 respawn: slave '/usr/share/vdsm/vdsm' died too quickly, respawning slave Jun 25 10:45:08 ovirt-node2 respawn: slave '/usr/share/vdsm/vdsm' died too quickly, respawning slave Jun 25 10:45:09 ovirt-node2 respawn: slave '/usr/share/vdsm/vdsm' died too quickly for more than 30 seconds, master sleeping for 900 seconds I don't know why Fedora 17 calls p36p1 to what was eth0 in Fedora 16, but tried to configure a bridge ovirtmgmt and the only difference is that KeyError becomes 'ovirtmgmt'. Regards, Jose Garcia

3 9

[Users] Following Up on LinuxCon Japan Workshop
by Leslie Hawthorn 25 Jun '12

25 Jun '12

Hello everyone, I'd like to collect feedback from everyone on last week's oVirt workshop at LinuxCon Japan. [0] Please reply back with comments by close of business this Friday, 15 June. Once we have gathered feedback on list, I'll capture it on the oVirt wiki. We can then use what we've learned to help construct the agenda and other plans for other upcoming oVirt workshops at LinuxCons. [1] If you know that you would like to volunteer as an instructor for future workshops or would like to suggest alternate content for the workshop, please include that in your feedback. - Course Material What sessions were most well received? Which ones require improvement? Any additional sessions we'd suggest? - Audience Participation How many attendees? How did the Q&A periods go? Would we like to prepare a post-event attendee survey? (I recommend we do the survey and can prepare some questions for the group if that's useful.) - Developer/user traction resulting from engaging at workshop Did this workshop help us to gain new developers or users? Reinforce relationships with existing community members? - Promotion of the event, both before and after What could be done to more effectively promote the event prior to the workshops? Videos and slides from the workshop should be posted on the LC Japan site tomorrow; what action would the community like to take to promote this content? - A/V and Room Set up Did the seating arrangements work well for the workshop format? Did the A/V work well, including the videotaping process? - Food and beverage Did the catered in lunch help to keep the flow of the workshop productive? Was the food of good quality and in keeping with the needs of attendee dietary constraints? - Give aways We did not produce attendee gifts for the oVirt workshop. Thoughts on whether this would be a welcome addition in the future? Suggestions for type of gift also welcome. - Any other feedback If it is preferable to discuss this feedback real-time, I will ask Mike Burns to give us more time for this topic during next week's oVirt IRC meeting. [0] - https://events.linuxfoundation.org/events/linuxcon-japan/ovirt-gluster-work… [1] - http://www.ovirt.org/wiki/OVirt_Global_Workshops Cheers, LH -- Leslie Hawthorn Community Action and Impact Open Source and Standards @ Red Hat identi.ca/lh twitter.com/lhawthorn

4 12

[Users] Call For Agenda Items -- oVirt Weekly Meeting 2012-06-20
by Mike Burns 25 Jun '12

25 Jun '12

The next oVirt Weekly Meeting is scheduled for 2012-06-20 at 15:00 UTC (10:00 AM EDT). Current Agenda Items (as of this email) * Status of Next Release * Sub-project reports (engine, vdsm, node) * Upcoming workshops Latest Agenda is listed here: http://www.ovirt.org/wiki/Meetings#Weekly_project_sync_meeting Reminder: If you propose an additional agenda item, please be present for the meeting to lead the discussion on it. Thanks Mike

1 1

[Users] direct lun
by ovirt＠qip.ru 25 Jun '12

25 Jun '12

This is a message in Mime Format. If you see this, your mail reader does not support this format. --=_33f249a1e3e46297f30fd6c611b989da Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable VM with attached direct lun not started with error in vm.log=0A=0Aqemu-k= vm: -drive file=3D/dev/mapper/1p_ISCSI_0_lun1,if=3Dnone,id=3Ddrive-virti= o-disk1,format=3Draw,serial=3D,cache=3Dnone,werror=3Dstop,rerror=3Dstop,= aio=3Dnative: could not open disk image /dev/mapper/1p_ISCSI_0_lun1: Per= mission denied=0A=0Ais this a bug or feature is not implemented yet?=0A= =0Aenv:=0Afedora17=0Aengine from http://www.ovirt.org/releases/beta/fedo= ra/17/=0Avdsm-4.10.0-0.57.git2987ee3.fc17.x86_64=0A=0A[root@kvm04 /]# ls= -l /dev/mapper/ | grep lun1=0Alrwxrwxrwx. 1 root root 7 Jun 25 14= :05 1p_ISCSI_0_lun1 -> ../dm-7=0A[root@kvm04 /]# ls -l /dev/ | grep dm-7= =0Abrw-rw----. 1 root disk 253, 7 Jun 25 14:05 dm-7=0A=0Ausermod -= a -G disk qemu solved the problem, but is it correct way to solve it?=0A= =0A-- --=_33f249a1e3e46297f30fd6c611b989da Content-Type: text/html; charset=utf-8 Content-Transfer-Encoding: quoted-printable VM with attached direct <= span id=3D"nicSpell_1" class=3D"nicSpellWord">lun not star= ted with error in vm.log qemu-kvm: -drive file=3D/dev/mapper/1p_ISCSI</= span>_0_lun1,if=3Dnone,id= =3Ddrive-virtio-disk1,format=3Draw,s= erial=3D,cache=3Dnone,<s= pan id=3D"nicSpell_11" class=3D"nicSpellWord">werror=3Dsto= p,rerror=3Dstop,aio=3Dnative: could not open disk image /dev/mapper/1p_ISCSI<= /span>_0_lun1: Permission d= enied is this a bug or feature is not implemented yet? <br= >env: fedora17 engine from http://www.ovirt.org/releases/beta/fedora/17/ vdsm-4.10.0-0.57.git2987ee3.fc17.x86_64= [root@kvm04 /]# ls -l /dev/mapper/ | grep lun1 lrwxrwx<sp= an id=3D"nicSpell_29" class=3D"nicSpellWord">rwx. 1 root root&nbs= p;      7 Jun 25 14:05 1p_ISCSI_0_lun1 -> ../dm-7 [root@kvm04 /]# ls -l /dev/ | grep dm-7 brw</span= >-rw----.&= nbsp; 1 root disk    253,   7 Jun 25 14:05 <spa= n id=3D"nicSpell_38" class=3D"nicSpellWord">dm-7 <span= id=3D"nicSpell_39" class=3D"nicSpellWord">usermod -a -G disk qem= u solved the problem, but is it correct way to solve it? --<b= r> --=_33f249a1e3e46297f30fd6c611b989da--

1 0

[Users] ovirt3.1 add node error
by tian b 25 Jun '12

25 Jun '12

Dear,all Can you help me? # tail /var/log/ovirt-engine/engine.log -f 2012-06-25 17:50:42,796 INFO [org.ovirt.engine.core.utils.hostinstall.HostKeyVerifier] (NioProcessor-21) SSH key fingerprint b4:f3:b9:4b:93:40:e8:9e:57:fc:b3:fe:b3:af:13:b4 for host 172.30.1.63 (172.30.1.63) has been successfully verified. 2012-06-25 17:50:42,872 INFO [org.ovirt.engine.core.utils.hostinstall.MinaInstallWrapper] (ajp--0.0.0.0-8009-3) Invoking /bin/echo -e `/bin/bash -c /usr/sbin/dmidecode|/bin/awk ' /UUID/{ print $2; } ' | /usr/bin/tr ' ' '_' && cat /sys/class/net/*/address | /bin/grep -v '00:00:00:00' | /bin/sort -u | /usr/bin/head --lines=1` on 172.30.1.63 2012-06-25 17:50:42,959 INFO [org.ovirt.engine.core.utils.hostinstall.MinaInstallWrapper] (ajp--0.0.0.0-8009-3) RunSSHCommand returns true 2012-06-25 17:50:42,985 INFO [org.ovirt.engine.core.bll.AddVdsCommand] (ajp--0.0.0.0-8009-3) [7d335777] Running command: AddVdsCommand internal: false. Entities affected : ID: 99408929-82cf-4dc7-a532-9d998063fa95 Type: VdsGroups 2012-06-25 17:50:43,017 INFO [org.ovirt.engine.core.bll.AddVdsSpmIdCommand] (ajp--0.0.0.0-8009-3) [318b963a] Running command: AddVdsSpmIdCommand internal: true. Entities affected : ID: 3a9d9a40-beab-11e1-9366-525400fe2d56 Type: VDS 2012-06-25 17:50:43,048 ERROR [org.ovirt.engine.core.vdsbroker.ResourceManager] (ajp--0.0.0.0-8009-3) [318b963a] Cannot get vdsManager for vdsid=3a9d9a40-beab-11e1-9366-525400fe2d56 2012-06-25 17:50:43,049 INFO [org.ovirt.engine.core.vdsbroker.RemoveVdsVDSCommand] (ajp--0.0.0.0-8009-3) [318b963a] START, RemoveVdsVDSCommand(vdsId = 3a9d9a40-beab-11e1-9366-525400fe2d56), log id: 7bd4b2c7 2012-06-25 17:50:43,051 ERROR [org.ovirt.engine.core.vdsbroker.ResourceManager] (ajp--0.0.0.0-8009-3) [318b963a] Cannot get vdsManager for vdsid=3a9d9a40-beab-11e1-9366-525400fe2d56 2012-06-25 17:50:43,052 INFO [org.ovirt.engine.core.vdsbroker.RemoveVdsVDSCommand] (ajp--0.0.0.0-8009-3) [318b963a] FINISH, RemoveVdsVDSCommand, log id: 7bd4b2c7 2012-06-25 17:50:43,053 ERROR [org.ovirt.engine.core.vdsbroker.ResourceManager] (ajp--0.0.0.0-8009-3) [318b963a] Cannot get vdsManager for vdsid=3a9d9a40-beab-11e1-9366-525400fe2d56 2012-06-25 17:50:43,054 INFO [org.ovirt.engine.core.vdsbroker.AddVdsVDSCommand] (ajp--0.0.0.0-8009-3) [318b963a] START, AddVdsVDSCommand(vdsId = 3a9d9a40-beab-11e1-9366-525400fe2d56), log id: 49256654 2012-06-25 17:50:43,056 INFO [org.ovirt.engine.core.vdsbroker.AddVdsVDSCommand] (ajp--0.0.0.0-8009-3) [318b963a] AddVds - entered , starting logic to add VDS 3a9d9a40-beab-11e1-9366-525400fe2d56 2012-06-25 17:50:43,059 INFO [org.ovirt.engine.core.vdsbroker.AddVdsVDSCommand] (ajp--0.0.0.0-8009-3) [318b963a] AddVds - VDS 3a9d9a40-beab-11e1-9366-525400fe2d56 was added, will try to add it to the resource manager 2012-06-25 17:50:43,062 INFO [org.ovirt.engine.core.vdsbroker.VdsManager] (ajp--0.0.0.0-8009-3) [318b963a] Eneterd VdsManager:constructor 2012-06-25 17:50:43,063 INFO [org.ovirt.engine.core.vdsbroker.VdsManager] (ajp--0.0.0.0-8009-3) [318b963a] vdsBroker(172.30.1.63,54,321) 2012-06-25 17:50:43,065 INFO [org.ovirt.engine.core.vdsbroker.ResourceManager] (ajp--0.0.0.0-8009-3) [318b963a] ResourceManager::AddVds - VDS 3a9d9a40-beab-11e1-9366-525400fe2d56 was added to the Resource Manager 2012-06-25 17:50:43,067 INFO [org.ovirt.engine.core.vdsbroker.AddVdsVDSCommand] (ajp--0.0.0.0-8009-3) [318b963a] FINISH, AddVdsVDSCommand, log id: 49256654 2012-06-25 17:50:43,098 INFO [org.ovirt.engine.core.bll.InstallVdsCommand] (pool-3-thread-49) [44a5dc80] Running command: InstallVdsCommand internal: true. Entities affected : ID: 3a9d9a40-beab-11e1-9366-525400fe2d56 Type: VDS 2012-06-25 17:50:43,102 INFO [org.ovirt.engine.core.bll.InstallVdsCommand] (pool-3-thread-49) [44a5dc80] Before Installation pool-3-thread-49 2012-06-25 17:50:43,103 INFO [org.ovirt.engine.core.bll.VdsInstaller] (pool-3-thread-49) [44a5dc80] Installation of 172.30.1.63. Executing installation stage. (Stage: Starting Host installation) 2012-06-25 17:50:43,105 INFO [org.ovirt.engine.core.bll.VdsInstaller] (pool-3-thread-49) [44a5dc80] Installation of 172.30.1.63. Executing installation stage. (Stage: Connecting to Host) 2012-06-25 17:50:43,134 INFO [org.ovirt.engine.core.utils.hostinstall.HostKeyVerifier] (NioProcessor-27) SSH key fingerprint b4:f3:b9:4b:93:40:e8:9e:57:fc:b3:fe:b3:af:13:b4 for host 172.30.1.63 (172.30.1.63) has been successfully verified. 2012-06-25 17:50:43,206 INFO [org.ovirt.engine.core.bll.VdsInstaller] (pool-3-thread-49) [44a5dc80] Installation of 172.30.1.63. Recieved message: <BSTRAP component='RHEV_INSTALL' status='OK' message='Connected to Host 172.30.1.63 with SSH key fingerprint: b4:f3:b9:4b:93:40:e8:9e:57:fc:b3:fe:b3:af:13:b4'/>. FYI. (Stage: Connecting to Host) 2012-06-25 17:50:43,223 INFO [org.ovirt.engine.core.bll.VdsInstaller] (pool-3-thread-49) [44a5dc80] Installation of 172.30.1.63. Successfully connected to server ssh. (Stage: Connecting to Host) 2012-06-25 17:50:43,224 INFO [org.ovirt.engine.core.bll.VdsInstaller] (pool-3-thread-49) [44a5dc80] Installation of 172.30.1.63. Executing installation stage. (Stage: Get the unique vds id) 2012-06-25 17:50:43,225 INFO [org.ovirt.engine.core.utils.hostinstall.MinaInstallWrapper] (pool-3-thread-49) Invoking /bin/echo -e `/bin/bash -c /usr/sbin/dmidecode|/bin/awk ' /UUID/{ print $2; } ' | /usr/bin/tr ' ' '_' && cat /sys/class/net/*/address | /bin/grep -v '00:00:00:00' | /bin/sort -u | /usr/bin/head --lines=1` on 172.30.1.63 2012-06-25 17:50:43,292 INFO [org.ovirt.engine.core.bll.VdsInstaller] (pool-3-thread-49) [44a5dc80] Installation of 172.30.1.63. Recieved message: 00010000-FE01-0300-00C4-43504C4400C7_00:23:8b:65:08:90 . FYI. (Stage: Get the unique vds id) 2012-06-25 17:50:43,306 INFO [org.ovirt.engine.core.bll.VdsInstaller] (pool-3-thread-49) [44a5dc80] Installation of 172.30.1.63. Assigning unique id 00010000-FE01-0300-00C4-43504C4400C7_00:23:8b:65:08:90 to Host. (Stage: Get the unique vds id) 2012-06-25 17:50:43,311 INFO [org.ovirt.engine.core.utils.hostinstall.MinaInstallWrapper] (pool-3-thread-49) RunSSHCommand returns true 2012-06-25 17:50:43,316 INFO [org.ovirt.engine.core.bll.VdsInstaller] (pool-3-thread-49) [44a5dc80] Installation of 172.30.1.63. Executing installation stage. (Stage: Upload Installation script to Host) 2012-06-25 17:50:43,325 INFO [org.ovirt.engine.core.utils.hostinstall.MinaInstallWrapper] (pool-3-thread-49) Uploading file /usr/share/ovirt-engine/scripts/vds_installer.py to /tmp/vds_installer_2ea9f19e-7e9d-46a5-bdfb-dc86532c1fe6.py on 172.30.1.63 2012-06-25 17:50:43,335 INFO [org.ovirt.engine.core.utils.hostinstall.MinaInstallWrapper] (pool-3-thread-49) Uploading file /usr/share/ovirt-engine/scripts/vds_installer.py to /tmp/vds_installer_2ea9f19e-7e9d-46a5-bdfb-dc86532c1fe6.py on 172.30.1.63 2012-06-25 17:50:43,668 INFO [org.ovirt.engine.core.bll.VdsInstaller] (pool-3-thread-49) [44a5dc80] Installation of 172.30.1.63. successfully done sftp operation ( Stage: Upload Installation script to Host) 2012-06-25 17:50:43,674 INFO [org.ovirt.engine.core.utils.hostinstall.MinaInstallWrapper] (pool-3-thread-49) return true 2012-06-25 17:50:43,676 INFO [org.ovirt.engine.core.utils.hostinstall.MinaInstallWrapper] (pool-3-thread-49) Uploading file /tmp/firewall.conf4248057098344742688.tmp to /tmp/firewall.conf.2ea9f19e-7e9d-46a5-bdfb-dc86532c1fe6 on 172.30.1.63 2012-06-25 17:50:43,678 INFO [org.ovirt.engine.core.utils.hostinstall.MinaInstallWrapper] (pool-3-thread-49) Uploading file /tmp/firewall.conf4248057098344742688.tmp to /tmp/firewall.conf.2ea9f19e-7e9d-46a5-bdfb-dc86532c1fe6 on 172.30.1.63 2012-06-25 17:50:43,965 INFO [org.ovirt.engine.core.bll.VdsInstaller] (pool-3-thread-49) [44a5dc80] Installation of 172.30.1.63. successfully done sftp operation ( Stage: Upload Installation script to Host) 2012-06-25 17:50:43,966 INFO [org.ovirt.engine.core.utils.hostinstall.MinaInstallWrapper] (pool-3-thread-49) return true 2012-06-25 17:50:43,967 INFO [org.ovirt.engine.core.bll.VdsInstaller] (pool-3-thread-49) [44a5dc80] Installation of 172.30.1.63. Executing installation stage. (Stage: Running first installation script on Host) 2012-06-25 17:50:43,968 INFO [org.ovirt.engine.core.bll.VdsInstaller] (pool-3-thread-49) [44a5dc80] Installation of 172.30.1.63. Sending SSH Command chmod +x /tmp/vds_installer_2ea9f19e-7e9d-46a5-bdfb-dc86532c1fe6.py; /tmp/vds_installer_2ea9f19e-7e9d-46a5-bdfb-dc86532c1fe6.py -c 'ssl=true;management_port=54321' -O 'oVirt' -t 2012-06-25T09:50:43 -f /tmp/firewall.conf.2ea9f19e-7e9d-46a5-bdfb-dc86532c1fe6 -p 80 -b http://fedora17.kvm.com:80/Components/vds/ http://fedora17.kvm.com:80/Components/vds/ 172.30.1.63 2ea9f19e-7e9d-46a5-bdfb-dc86532c1fe6 False. (Stage: Running first installation script on Host) 2012-06-25 17:50:43,971 INFO [org.ovirt.engine.core.utils.hostinstall.MinaInstallWrapper] (pool-3-thread-49) Invoking chmod +x /tmp/vds_installer_2ea9f19e-7e9d-46a5-bdfb-dc86532c1fe6.py; /tmp/vds_installer_2ea9f19e-7e9d-46a5-bdfb-dc86532c1fe6.py -c 'ssl=true;management_port=54321' -O 'oVirt' -t 2012-06-25T09:50:43 -f /tmp/firewall.conf.2ea9f19e-7e9d-46a5-bdfb-dc86532c1fe6 -p 80 -b http://fedora17.kvm.com:80/Components/vds/ http://fedora17.kvm.com:80/Components/vds/ 172.30.1.63 2ea9f19e-7e9d-46a5-bdfb-dc86532c1fe6 False on 172.30.1.63 2012-06-25 17:50:44,040 WARN [org.ovirt.engine.core.ServletUtils] (ajp--0.0.0.0-8009-5) File "/usr/share/vdsm-bootstrap/vds_bootstrap.py is 33883 bytes long. Please reconsider using this servlet for files larger than 8192 bytes. 2012-06-25 17:50:44,976 INFO [org.ovirt.engine.core.bll.VdsInstaller] (pool-3-thread-49) [44a5dc80] Installation of 172.30.1.63. Recieved message: <BSTRAP component='RHEV_INSTALL' status='OK' message='oVirt Node DETECTED'/> <BSTRAP component='INSTALLER LIB' status='OK' message='Install library already exists'/> <BSTRAP component='INSTALLER' status='OK' message='vds_bootstrap.py download succeeded'/> . FYI. (Stage: Running first installation script on Host) 2012-06-25 17:50:45,067 INFO [org.ovirt.engine.core.vdsbroker.VdsManager] (QuartzScheduler_Worker-55) Initializing Host: node3.kvm.com 2012-06-25 17:50:45,345 INFO [org.ovirt.engine.core.bll.VdsInstaller] (pool-3-thread-49) [44a5dc80] Installation of 172.30.1.63. Recieved message: <BSTRAP component='RHEV_INSTALL' status='OK' message='RHEV-H ACCESSIBLE'/> . Stage completed. (Stage: Running first installation script on Host) 2012-06-25 17:50:45,362 INFO [org.ovirt.engine.core.utils.hostinstall.MinaInstallWrapper] (pool-3-thread-49) RunSSHCommand returns true 2012-06-25 17:50:45,369 INFO [org.ovirt.engine.core.bll.VdsInstaller] (pool-3-thread-49) [44a5dc80] RunScript ended:true 2012-06-25 17:50:45,369 INFO [org.ovirt.engine.core.bll.RegisterVdsQuery] (ajp--0.0.0.0-8009-1) Running Command: RegisterVds 2012-06-25 17:50:45,378 INFO [org.ovirt.engine.core.bll.InstallVdsCommand] (pool-3-thread-49) [44a5dc80] After Installation pool-3-thread-49 2012-06-25 17:50:45,388 INFO [org.ovirt.engine.core.bll.ApproveVdsCommand] (pool-3-thread-50) [40044463] Running command: ApproveVdsCommand internal: true. Entities affected : ID: 3a9d9a40-beab-11e1-9366-525400fe2d56 Type: VDS 2012-06-25 17:50:45,390 INFO [org.ovirt.engine.core.bll.InstallVdsCommand] (pool-3-thread-50) [40044463] Before Installation pool-3-thread-50, Powerclient/oVirtNode case: setting status to installing 2012-06-25 17:50:45,393 INFO [org.ovirt.engine.core.vdsbroker.SetVdsStatusVDSCommand] (pool-3-thread-50) [40044463] START, SetVdsStatusVDSCommand(vdsId = 3a9d9a40-beab-11e1-9366-525400fe2d56, status=Installing, nonOperationalReason=NONE), log id: ee6f19 2012-06-25 17:50:45,395 INFO [org.ovirt.engine.core.register.RegisterServlet] (ajp--0.0.0.0-8009-1) Succeeded to run RegisterVds. 2012-06-25 17:50:45,407 INFO [org.ovirt.engine.core.vdsbroker.SetVdsStatusVDSCommand] (pool-3-thread-50) [40044463] FINISH, SetVdsStatusVDSCommand, log id: ee6f19 2012-06-25 17:50:45,418 INFO [org.ovirt.engine.core.bll.InstallVdsCommand] (pool-3-thread-50) [40044463] Before Installation pool-3-thread-50 2012-06-25 17:50:45,424 INFO [org.ovirt.engine.core.bll.CBCInstaller] (pool-3-thread-50) [40044463] Installation of 172.30.1.63. Executing oVirt installation stage. (Stage: Starting Host installation) 2012-06-25 17:50:45,432 INFO [org.ovirt.engine.core.bll.CBCInstaller] (pool-3-thread-50) [40044463] Installation of 172.30.1.63. Executing oVirt installation stage. (Stage: Connecting to Host) 2012-06-25 17:50:45,471 INFO [org.ovirt.engine.core.utils.hostinstall.HostKeyVerifier] (NioProcessor-33) SSH key fingerprint b4:f3:b9:4b:93:40:e8:9e:57:fc:b3:fe:b3:af:13:b4 for host 172.30.1.63 (172.30.1.63) has been successfully verified. 2012-06-25 17:50:45,556 INFO [org.ovirt.engine.core.bll.VdsInstaller] (pool-3-thread-50) [40044463] Installation of 172.30.1.63. Recieved message: <BSTRAP component='RHEV_INSTALL' status='OK' message='Connected to Host 172.30.1.63 with SSH key fingerprint: b4:f3:b9:4b:93:40:e8:9e:57:fc:b3:fe:b3:af:13:b4'/>. FYI. (Stage: Connecting to Host) 2012-06-25 17:50:45,580 INFO [org.ovirt.engine.core.bll.VdsInstaller] (pool-3-thread-50) [40044463] Installation of 172.30.1.63. Successfully connected to server ssh. (Stage: Connecting to Host) 2012-06-25 17:50:45,588 INFO [org.ovirt.engine.core.bll.CBCInstaller] (pool-3-thread-50) [40044463] Installation of 172.30.1.63. Executing oVirt installation stage. (Stage: Running first installation script on Host) 2012-06-25 17:50:45,590 INFO [org.ovirt.engine.core.utils.hostinstall.MinaInstallWrapper] (pool-3-thread-50) Invoking /usr/share/vdsm-reg/vdsm-gen-cert -O "oVirt" 172.30.1.63 97174773-9fa8-46af-9e31-46307330aeac on 172.30.1.63 2012-06-25 17:50:56,379 INFO [org.ovirt.engine.core.bll.VdsInstaller] (pool-3-thread-50) [40044463] Installation of 172.30.1.63. Recieved message: <BSTRAP component='Encryption setup' status='OK'/> <BSTRAP component='RHEV_INSTALL' status='OK'/> . Stage completed. (Stage: Running first installation script on Host) 2012-06-25 17:50:56,393 INFO [org.ovirt.engine.core.utils.hostinstall.MinaInstallWrapper] (pool-3-thread-50) RunSSHCommand returns true 2012-06-25 17:50:56,394 INFO [org.ovirt.engine.core.bll.CBCInstaller] (pool-3-thread-50) [40044463] Installation of 172.30.1.63. Executing oVirt installation stage. (Stage: Downloading certificate request from Host) 2012-06-25 17:50:56,395 INFO [org.ovirt.engine.core.utils.hostinstall.MinaInstallWrapper] (pool-3-thread-50) Downloading file /tmp/cert_97174773-9fa8-46af-9e31-46307330aeac.req from 172.30.1.63 to /etc/pki/ovirt-engine/requests/cert_97174773-9fa8-46af-9e31-46307330aeac.req 2012-06-25 17:50:56,680 INFO [org.ovirt.engine.core.bll.VdsInstaller] (pool-3-thread-50) [40044463] Installation of 172.30.1.63. successfully done sftp operation ( Stage: Downloading certificate request from Host) 2012-06-25 17:50:56,688 INFO [org.ovirt.engine.core.utils.hostinstall.MinaInstallWrapper] (pool-3-thread-50) return true 2012-06-25 17:50:56,693 INFO [org.ovirt.engine.core.bll.VdsInstaller] (pool-3-thread-50) [40044463] DownloadCertificateRequest ended:true 2012-06-25 17:50:56,699 INFO [org.ovirt.engine.core.bll.CBCInstaller] (pool-3-thread-50) [40044463] Installation of 172.30.1.63. Executing oVirt installation stage. (Stage: Sign certificate request and generate certificate) 2012-06-25 17:50:57,713 INFO [org.ovirt.engine.core.bll.VdsInstaller] (pool-3-thread-50) [40044463] SignCertificateRequest ended:true 2012-06-25 17:50:57,718 INFO [org.ovirt.engine.core.bll.CBCInstaller] (pool-3-thread-50) [40044463] Installation of 172.30.1.63. Executing oVirt installation stage. (Stage: Upload signed sertificate to Host) 2012-06-25 17:50:57,724 INFO [org.ovirt.engine.core.utils.hostinstall.MinaInstallWrapper] (pool-3-thread-50) Uploading file /etc/pki/ovirt-engine/certs/172.30.1.63cert.pem to /tmp/cert_97174773-9fa8-46af-9e31-46307330aeac.pem on 172.30.1.63 2012-06-25 17:50:57,726 INFO [org.ovirt.engine.core.utils.hostinstall.MinaInstallWrapper] (pool-3-thread-50) Uploading file /etc/pki/ovirt-engine/certs/172.30.1.63cert.pem to /tmp/cert_97174773-9fa8-46af-9e31-46307330aeac.pem on 172.30.1.63 2012-06-25 17:50:57,988 INFO [org.ovirt.engine.core.bll.VdsInstaller] (pool-3-thread-50) [40044463] Installation of 172.30.1.63. successfully done sftp operation ( Stage: Upload signed sertificate to Host) 2012-06-25 17:50:57,989 INFO [org.ovirt.engine.core.utils.hostinstall.MinaInstallWrapper] (pool-3-thread-50) return true 2012-06-25 17:50:57,990 INFO [org.ovirt.engine.core.bll.VdsInstaller] (pool-3-thread-50) [40044463] UploadSignedCertificate ended:true 2012-06-25 17:50:57,991 INFO [org.ovirt.engine.core.bll.CBCInstaller] (pool-3-thread-50) [40044463] Installation of 172.30.1.63. Executing oVirt installation stage. (Stage: Upload Cerficate Autority to Host) 2012-06-25 17:50:57,992 INFO [org.ovirt.engine.core.utils.hostinstall.MinaInstallWrapper] (pool-3-thread-50) Uploading file /etc/pki/ovirt-engine/ca.pem to /tmp/CA_97174773-9fa8-46af-9e31-46307330aeac.pem on 172.30.1.63 2012-06-25 17:50:57,994 INFO [org.ovirt.engine.core.utils.hostinstall.MinaInstallWrapper] (pool-3-thread-50) Uploading file /etc/pki/ovirt-engine/ca.pem to /tmp/CA_97174773-9fa8-46af-9e31-46307330aeac.pem on 172.30.1.63 2012-06-25 17:50:58,249 INFO [org.ovirt.engine.core.bll.VdsInstaller] (pool-3-thread-50) [40044463] Installation of 172.30.1.63. successfully done sftp operation ( Stage: Upload Cerficate Autority to Host) 2012-06-25 17:50:58,258 INFO [org.ovirt.engine.core.utils.hostinstall.MinaInstallWrapper] (pool-3-thread-50) return true 2012-06-25 17:50:58,263 INFO [org.ovirt.engine.core.bll.CBCInstaller] (pool-3-thread-50) [40044463] Installation of 172.30.1.63. Executing oVirt installation stage, sending SSH Command /usr/share/vdsm-reg/vdsm-complete -c 'ssl=true' 97174773-9fa8-46af-9e31-46307330aeac 0. (Stage: Running second installation script on Host) 2012-06-25 17:50:58,267 INFO [org.ovirt.engine.core.utils.hostinstall.MinaInstallWrapper] (pool-3-thread-50) Invoking /usr/share/vdsm-reg/vdsm-complete -c 'ssl=true' 97174773-9fa8-46af-9e31-46307330aeac 0 on 172.30.1.63 2012-06-25 17:51:02,269 INFO [org.ovirt.engine.core.bll.VdsInstaller] (pool-3-thread-50) [40044463] Installation of 172.30.1.63. Recieved message: <BSTRAP component='instCert' status='OK'/> <BSTRAP component='CoreDump' status='OK'/> <BSTRAP component='cleanAll' status='OK'/> <BSTRAP component='VDS Configuration' status='OK'/> <BSTRAP component='Restart' status='OK' message='Restarting vdsmd service' /> <BSTRAP component='RHEV_INSTALL' status='OK'/> . Stage completed. (Stage: Running second installation script on Host) 2012-06-25 17:51:02,317 INFO [org.ovirt.engine.core.utils.hostinstall.MinaInstallWrapper] (pool-3-thread-50) RunSSHCommand returns true 2012-06-25 17:51:02,318 INFO [org.ovirt.engine.core.bll.InstallVdsCommand] (pool-3-thread-50) [40044463] After Installation pool-3-thread-50 2012-06-25 17:51:02,319 INFO [org.ovirt.engine.core.vdsbroker.SetVdsStatusVDSCommand] (pool-3-thread-50) [40044463] START, SetVdsStatusVDSCommand(vdsId = 3a9d9a40-beab-11e1-9366-525400fe2d56, status=NonResponsive, nonOperationalReason=NONE), log id: 513cfcb8 2012-06-25 17:51:02,343 INFO [org.ovirt.engine.core.vdsbroker.SetVdsStatusVDSCommand] (pool-3-thread-50) [40044463] FINISH, SetVdsStatusVDSCommand, log id: 513cfcb8 2012-06-25 17:51:02,351 INFO [org.ovirt.engine.core.vdsbroker.SetVdsStatusVDSCommand] (pool-3-thread-50) [40044463] START, SetVdsStatusVDSCommand(vdsId = 3a9d9a40-beab-11e1-9366-525400fe2d56, status=Unassigned, nonOperationalReason=NONE), log id: 36058f20 2012-06-25 17:51:02,367 INFO [org.ovirt.engine.core.vdsbroker.SetVdsStatusVDSCommand] (pool-3-thread-50) [40044463] FINISH, SetVdsStatusVDSCommand, log id: 36058f20 2012-06-25 17:51:02,372 INFO [org.ovirt.engine.core.bll.RegisterVdsQuery] (pool-3-thread-50) [40044463] Approval of oVirt 3a9d9a40-beab-11e1-9366-525400fe2d56 ended successefully. 2012-06-25 17:51:03,109 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand] (QuartzScheduler_Worker-83) XML RPC error in command GetCapabilitiesVDS ( Vds: node3.kvm.com ), the error was: java.util.concurrent.ExecutionException: java.lang.reflect.InvocationTargetException, EOFException: SSL peer shut down incorrectly 2012-06-25 17:51:03,115 WARN [org.ovirt.engine.core.vdsbroker.VdsManager] (QuartzScheduler_Worker-83) ResourceManager::refreshVdsRunTimeInfo::Failed to refresh VDS , vds = 3a9d9a40-beab-11e1-9366-525400fe2d56 : node3.kvm.com, VDS Network Error, continuing. VDSNetworkException: 2012-06-25 17:51:05,127 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand] (QuartzScheduler_Worker-95) XML RPC error in command GetCapabilitiesVDS ( Vds: node3.kvm.com ), the error was: java.util.concurrent.ExecutionException: java.lang.reflect.InvocationTargetException, EOFException: SSL peer shut down incorrectly 2012-06-25 17:51:05,140 WARN [org.ovirt.engine.core.vdsbroker.VdsManager] (QuartzScheduler_Worker-95) ResourceManager::refreshVdsRunTimeInfo::Failed to refresh VDS , vds = 3a9d9a40-beab-11e1-9366-525400fe2d56 : node3.kvm.com, VDS Network Error, continuing. VDSNetworkException: 2012-06-25 17:51:07,162 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand] (QuartzScheduler_Worker-76) XML RPC error in command GetCapabilitiesVDS ( Vds: node3.kvm.com ), the error was: java.util.concurrent.ExecutionException: java.lang.reflect.InvocationTargetException, EOFException: SSL peer shut down incorrectly 2012-06-25 17:51:07,170 WARN [org.ovirt.engine.core.vdsbroker.VdsManager] (QuartzScheduler_Worker-76) ResourceManager::refreshVdsRunTimeInfo::Failed to refresh VDS , vds = 3a9d9a40-beab-11e1-9366-525400fe2d56 : node3.kvm.com, VDS Network Error, continuing. VDSNetworkException: 2012-06-25 17:51:09,187 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand] (QuartzScheduler_Worker-84) XML RPC error in command GetCapabilitiesVDS ( Vds: node3.kvm.com ), the error was: java.util.concurrent.ExecutionException: java.lang.reflect.InvocationTargetException, EOFException: SSL peer shut down incorrectly 2012-06-25 17:51:09,189 WARN [org.ovirt.engine.core.vdsbroker.VdsManager] (QuartzScheduler_Worker-84) ResourceManager::refreshVdsRunTimeInfo::Failed to refresh VDS , vds = 3a9d9a40-beab-11e1-9366-525400fe2d56 : node3.kvm.com, VDS Network Error, continuing. VDSNetworkException: 2012-06-25 17:51:11,202 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand] (QuartzScheduler_Worker-91) XML RPC error in command GetCapabilitiesVDS ( Vds: node3.kvm.com ), the error was: java.util.concurrent.ExecutionException: java.lang.reflect.InvocationTargetException, EOFException: SSL peer shut down incorrectly 2012-06-25 17:51:11,204 WARN [org.ovirt.engine.core.vdsbroker.VdsManager] (QuartzScheduler_Worker-91) ResourceManager::refreshVdsRunTimeInfo::Failed to refresh VDS , vds = 3a9d9a40-beab-11e1-9366-525400fe2d56 : node3.kvm.com, VDS Network Error, continuing. VDSNetworkException: 2012-06-25 17:51:13,217 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand] (QuartzScheduler_Worker-88) XML RPC error in command GetCapabilitiesVDS ( Vds: node3.kvm.com ), the error was: java.util.concurrent.ExecutionException: java.lang.reflect.InvocationTargetException, EOFException: SSL peer shut down incorrectly 2012-06-25 17:51:13,219 WARN [org.ovirt.engine.core.vdsbroker.VdsManager] (QuartzScheduler_Worker-88) ResourceManager::refreshVdsRunTimeInfo::Failed to refresh VDS , vds = 3a9d9a40-beab-11e1-9366-525400fe2d56 : node3.kvm.com, VDS Network Error, continuing. VDSNetworkException: 2012-06-25 17:51:15,240 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand] (QuartzScheduler_Worker-8) XML RPC error in command GetCapabilitiesVDS ( Vds: node3.kvm.com ), the error was: java.util.concurrent.ExecutionException: java.lang.reflect.InvocationTargetException, EOFException: SSL peer shut down incorrectly 2012-06-25 17:51:15,245 WARN [org.ovirt.engine.core.vdsbroker.VdsManager] (QuartzScheduler_Worker-8) ResourceManager::refreshVdsRunTimeInfo::Failed to refresh VDS , vds = 3a9d9a40-beab-11e1-9366-525400fe2d56 : node3.kvm.com, VDS Network Error, continuing. VDSNetworkException: 2012-06-25 17:51:17,260 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand] (QuartzScheduler_Worker-5) XML RPC error in command GetCapabilitiesVDS ( Vds: node3.kvm.com ), the error was: java.util.concurrent.ExecutionException: java.lang.reflect.InvocationTargetException, EOFException: SSL peer shut down incorrectly 2012-06-25 17:51:17,262 WARN [org.ovirt.engine.core.vdsbroker.VdsManager] (QuartzScheduler_Worker-5) ResourceManager::refreshVdsRunTimeInfo::Failed to refresh VDS , vds = 3a9d9a40-beab-11e1-9366-525400fe2d56 : node3.kvm.com, VDS Network Error, continuing. VDSNetworkException: # ping node3.kvm.com PING node3.kvm.com (172.30.1.63) 56(84) bytes of data. 64 bytes from 172.30.1.63: icmp_req=1 ttl=64 time=0.325 ms # ping `hostname` PING fedora17-ovirt.kvm.com (172.30.1.30) 56(84) bytes of data. 64 bytes from fedora17-ovirt.kvm.com (172.30.1.30): icmp_req=1 ttl=64 time=0.036 ms # systemctl status jboss-as.service jboss-as.service - The JBoss Application Server Loaded: loaded (/usr/lib/systemd/system/jboss-as.service; enabled) Active: active (running) since Mon, 25 Jun 2012 17:29:06 +0800; 24min ago Main PID: 4873 (standalone.sh) CGroup: name=systemd:/system/jboss-as.service ├ 4873 /bin/sh /usr/share/jboss-as/bin/standalone.sh -c standalone-web.xml └ 4925 java -D[Standalone] -server -XX:+UseCompressedOops -XX:+TieredCompilation -Xms64m -Xmx512m -XX:MaxPermSize=256m -Djava.net.preferIPv4Stack=true -Dorg.j... # systemctl status libvirtd.service libvirtd.service - Virtualization daemon Loaded: loaded (/usr/lib/systemd/system/libvirtd.service; enabled) Active: active (running) since Mon, 25 Jun 2012 17:10:36 +0800; 43min ago Main PID: 3567 (libvirtd) CGroup: name=systemd:/system/libvirtd.service └ 3567 /usr/sbin/libvirtd --listen Jun 25 17:10:36 fedora17-ovirt.kvm.com libvirtd[3567]: Could not find keytab file: /etc/libvirt/krb5.tab: No such file or directory Jun 25 17:10:36 fedora17-ovirt.kvm.com libvirtd[3567]: server add_plugin entry_point error generic failure Jun 25 17:10:36 fedora17-ovirt.kvm.com libvirtd[3567]: _sasl_plugin_load failed on sasl_server_plug_init for plugin: gssapiv2 # systemctl status vdsmd.service vdsmd.service - Virtual Desktop Server Manager Loaded: loaded (/usr/lib/systemd/system/vdsmd.service; enabled) Active: active (running) since Mon, 25 Jun 2012 17:22:22 +0800; 31min ago Main PID: 4630 (respawn) CGroup: name=systemd:/system/vdsmd.service ├ 4630 /bin/bash -e /usr/share/vdsm/respawn --minlifetime 10 --daemon --masterpid /var/run/vdsm/respawn.pid /usr/share/vdsm/vdsm ├ 4633 /usr/bin/python /usr/share/vdsm/vdsm ├ 4653 /usr/bin/sudo -n /usr/bin/python /usr/share/vdsm/supervdsmServer.py 3eaebf05-cc78-4d61-abfe-9e675fcaf1b8 4633 └ 4654 /usr/bin/python /usr/share/vdsm/supervdsmServer.py 3eaebf05-cc78-4d61-abfe-9e675fcaf1b8 4633 Jun 25 17:22:20 fedora17-ovirt.kvm.com systemd-vdsmd[4396]: Starting iscsid: Jun 25 17:22:20 fedora17-ovirt.kvm.com systemd-vdsmd[4396]: Starting libvirtd (via systemctl): [ OK ] Jun 25 17:22:21 fedora17-ovirt.kvm.com systemd-vdsmd[4396]: Starting up vdsm daemon: Jun 25 17:22:21 fedora17-ovirt.kvm.com runuser[4627]: pam_unix(runuser:session): session opened for user vdsm by (uid=0) Jun 25 17:22:21 fedora17-ovirt.kvm.com runuser[4627]: pam_unix(runuser:session): session closed for user vdsm Jun 25 17:22:22 fedora17-ovirt.kvm.com systemd-vdsmd[4396]: [27B blob data] Jun 25 17:22:22 fedora17-ovirt.kvm.com python[4633]: DIGEST-MD5 client step 2 Jun 25 17:22:22 fedora17-ovirt.kvm.com python[4633]: DIGEST-MD5 client step 2 Jun 25 17:22:22 fedora17-ovirt.kvm.com python[4633]: DIGEST-MD5 client step 3 Jun 25 17:22:25 fedora17-ovirt.kvm.com vdsm[4633]: vdsm vds ERROR Unable to load the rest server module. Please make sure it is installed.

2 1

[Users] Do not start the virtual machine (gluster storage and ovirt 3.1)
by зоррыч 25 Jun '12

25 Jun '12

This is a multi-part message in MIME format. ------=_NextPart_000_00B5_01CD50A1.2C0D2C70 Content-Type: text/plain; charset="koi8-r" Content-Transfer-Encoding: 7bit Hi. I use a bunch of ovirt 3.1 beta and gluster storage. The virtual machine was created successfully, but will not start. In the logs: Vdsm.log: Thread-1426::DEBUG::2012-06-22 09:37:27,151::task::978::TaskManager.Task::(_decref) Task=`9a68c120-169f-4c0e-98e3-08e3bf5c66ab`::ref 0 aborting False Thread-1427::DEBUG::2012-06-22 09:37:27,162::BindingXMLRPC::160::vds::(wrapper) [10.1.20.2] Thread-1427::DEBUG::2012-06-22 09:37:27,163::task::588::TaskManager.Task::(_updateState) Task=`662a52dd-f00d-4be1-941d-eac8ec6a70f6`::moving from state init -> state preparing Thread-1427::INFO::2012-06-22 09:37:27,163::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='b1c7875a-964d-4633-8ea4-2b191d68c105', options=None) Thread-1427::DEBUG::2012-06-22 09:37:27,163::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.b1c7875a-964d-4633-8ea4-2b191d68c105`ReqID=`ca9b7715-1f0b-4 225-9717-d1179193c42e`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource' Thread-1427::DEBUG::2012-06-22 09:37:27,164::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.b1c7875a-964d-4633-8ea4-2b191d68c105' for lock type 'shared' Thread-1427::DEBUG::2012-06-22 09:37:27,164::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.b1c7875a-964d-4633-8ea4-2b191d68c105' is free. Now locking as 'shared' (1 active user) Thread-1427::DEBUG::2012-06-22 09:37:27,164::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.b1c7875a-964d-4633-8ea4-2b191d68c105`ReqID=`ca9b7715-1f0b-4 225-9717-d1179193c42e`::Granted request Thread-1427::DEBUG::2012-06-22 09:37:27,164::task::817::TaskManager.Task::(resourceAcquired) Task=`662a52dd-f00d-4be1-941d-eac8ec6a70f6`::_resourcesAcquired: Storage.b1c7875a-964d-4633-8ea4-2b191d68c105 (shared) Thread-1427::DEBUG::2012-06-22 09:37:27,165::task::978::TaskManager.Task::(_decref) Task=`662a52dd-f00d-4be1-941d-eac8ec6a70f6`::ref 1 aborting False Thread-1427::INFO::2012-06-22 09:37:27,165::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '68aa0dc2-9cd1-4549-8008-30b1bae667db', 'name': 'gluster', 'version': '0', 'domains': '68aa0dc2-9cd1-4549-8008-30b1bae667db:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'SHAREDFS', 'master_ver': 1, 'lver': 0}, 'dominfo': {'68aa0dc2-9cd1-4549-8008-30b1bae667db': {'status': 'Active', 'diskfree': '27505983488', 'alerts': [], 'disktotal': '53579874304'}}} Thread-1427::DEBUG::2012-06-22 09:37:27,165::task::1172::TaskManager.Task::(prepare) Task=`662a52dd-f00d-4be1-941d-eac8ec6a70f6`::finished: {'info': {'spm_id': 1, 'master_uuid': '68aa0dc2-9cd1-4549-8008-30b1bae667db', 'name': 'gluster', 'version': '0', 'domains': '68aa0dc2-9cd1-4549-8008-30b1bae667db:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'SHAREDFS', 'master_ver': 1, 'lver': 0}, 'dominfo': {'68aa0dc2-9cd1-4549-8008-30b1bae667db': {'status': 'Active', 'diskfree': '27505983488', 'alerts': [], 'disktotal': '53579874304'}}} Thread-1427::DEBUG::2012-06-22 09:37:27,166::task::588::TaskManager.Task::(_updateState) Task=`662a52dd-f00d-4be1-941d-eac8ec6a70f6`::moving from state preparing -> state finished Thread-1427::DEBUG::2012-06-22 09:37:27,166::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.b1c7875a-964d-4633-8ea4-2b191d68c105': < ResourceRef 'Storage.b1c7875a-964d-4633-8ea4-2b191d68c105', isValid: 'True' obj: 'None'>} Thread-1427::DEBUG::2012-06-22 09:37:27,166::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-1427::DEBUG::2012-06-22 09:37:27,166::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.b1c7875a-964d-4633-8ea4-2b191d68c105' Thread-1427::DEBUG::2012-06-22 09:37:27,166::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.b1c7875a-964d-4633-8ea4-2b191d68c105' (0 active users) Thread-1427::DEBUG::2012-06-22 09:37:27,167::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.b1c7875a-964d-4633-8ea4-2b191d68c105' is free, finding out if anyone is waiting for it. Thread-1427::DEBUG::2012-06-22 09:37:27,167::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.b1c7875a-964d-4633-8ea4-2b191d68c105', Clearing records. Thread-1427::DEBUG::2012-06-22 09:37:27,167::task::978::TaskManager.Task::(_decref) Task=`662a52dd-f00d-4be1-941d-eac8ec6a70f6`::ref 0 aborting False Thread-1428::DEBUG::2012-06-22 09:37:27,476::BindingXMLRPC::872::vds::(wrapper) client [10.1.20.2]::call vmCreate with ({'custom': {}, 'keyboardLayout': 'en-us', 'kvmEnable': 'true', 'acpiEnable': 'true', 'emulatedMachine': 'pc', 'tabletEnable': 'true', 'vmId': '92de99e5-067a-421b-a4b1-2a2b60e8894a', 'devices': [{'device': 'qxl', 'specParams': {'vram': '65536'}, 'type': 'video', 'deviceId': '9780f3aa-4c0e-44eb-bc94-7ebfb63fe2f3'}, {'index': '2', 'iface': 'ide', 'specParams': {'path': ''}, 'readonly': 'true', 'deviceId': '59b3e477-8ba9-4a09-ac4a-4d0da91708ce', 'device': 'cdrom', 'path': '', 'type': 'disk'}, {'index': 0, 'iface': 'virtio', 'format': 'raw', 'bootOrder': '1', 'volumeID': 'eb866d5a-1319-4e32-b9f3-4de3ad3272fb', 'imageID': '61180d3c-63ba-41ca-989a-8bd2acff4d7e', 'specParams': {}, 'readonly': 'false', 'domainID': '68aa0dc2-9cd1-4549-8008-30b1bae667db', 'optional': 'false', 'deviceId': '61180d3c-63ba-41ca-989a-8bd2acff4d7e', 'poolID': 'b1c7875a-964d-4633-8ea4-2b191d68c105', 'device': 'disk', 'shared': 'false', 'propagateErrors': 'off', 'type': 'disk'}, {'nicModel': 'pv', 'macAddr': '00:1a:4a:01:14:00', 'network': 'ovirtmgmt', 'specParams': {}, 'deviceId': 'c580b531-2178-4a38-bb1e-971bf300bf8a', 'device': 'bridge', 'type': 'interface'}, {'device': 'memballoon', 'specParams': {'model': 'virtio'}, 'type': 'balloon', 'deviceId': '3df4e23d-85bd-41b3-a320-3a510a1c2e7f'}], 'smp': '1', 'vmType': 'kvm', 'timeOffset': '0', 'memSize': 512, 'spiceSslCipherSuite': 'DEFAULT', 'cpuType': 'Conroe', 'spiceSecureChannels': 'smain,sinputs,scursor,splayback,srecord,sdisplay', 'smpCoresPerSocket': '1', 'vmName': 'fgjh', 'display': 'vnc', 'transparentHugePages': 'true', 'nice': '0'},) {} flowID [60053096] Thread-1428::INFO::2012-06-22 09:37:27,477::API::603::vds::(_getNetworkIp) network None: using 0 Thread-1428::INFO::2012-06-22 09:37:27,477::API::229::vds::(create) vmContainerLock acquired by vm 92de99e5-067a-421b-a4b1-2a2b60e8894a Thread-1429::DEBUG::2012-06-22 09:37:27,479::vm::564::vm.Vm::(_startUnderlyingVm) vmId=`92de99e5-067a-421b-a4b1-2a2b60e8894a`::Start Thread-1428::DEBUG::2012-06-22 09:37:27,479::API::246::vds::(create) Total desktops after creation of 92de99e5-067a-421b-a4b1-2a2b60e8894a is 1 Thread-1428::DEBUG::2012-06-22 09:37:27,480::BindingXMLRPC::879::vds::(wrapper) return vmCreate with {'status': {'message': 'Done', 'code': 0}, 'vmList': {'status': 'WaitForLaunch', 'acpiEnable': 'true', 'emulatedMachine': 'pc', 'tabletEnable': 'true', 'pid': '0', 'timeOffset': '0', 'displayPort': '-1', 'displaySecurePort': '-1', 'spiceSslCipherSuite': 'DEFAULT', 'cpuType': 'Conroe', 'custom': {}, 'clientIp': '', 'nicModel': 'rtl8139,pv', 'keyboardLayout': 'en-us', 'kvmEnable': 'true', 'vmId': '92de99e5-067a-421b-a4b1-2a2b60e8894a', 'transparentHugePages': 'true', 'devices': [{'device': 'qxl', 'specParams': {'vram': '65536'}, 'type': 'video', 'deviceId': '9780f3aa-4c0e-44eb-bc94-7ebfb63fe2f3'}, {'index': '2', 'iface': 'ide', 'specParams': {'path': ''}, 'readonly': 'true', 'deviceId': '59b3e477-8ba9-4a09-ac4a-4d0da91708ce', 'device': 'cdrom', 'path': '', 'type': 'disk'}, {'index': 0, 'iface': 'virtio', 'format': 'raw', 'bootOrder': '1', 'volumeID': 'eb866d5a-1319-4e32-b9f3-4de3ad3272fb', 'imageID': '61180d3c-63ba-41ca-989a-8bd2acff4d7e', 'specParams': {}, 'readonly': 'false', 'domainID': '68aa0dc2-9cd1-4549-8008-30b1bae667db', 'optional': 'false', 'deviceId': '61180d3c-63ba-41ca-989a-8bd2acff4d7e', 'poolID': 'b1c7875a-964d-4633-8ea4-2b191d68c105', 'device': 'disk', 'shared': 'false', 'propagateErrors': 'off', 'type': 'disk'}, {'nicModel': 'pv', 'macAddr': '00:1a:4a:01:14:00', 'network': 'ovirtmgmt', 'specParams': {}, 'deviceId': 'c580b531-2178-4a38-bb1e-971bf300bf8a', 'device': 'bridge', 'type': 'interface'}, {'device': 'memballoon', 'specParams': {'model': 'virtio'}, 'type': 'balloon', 'deviceId': '3df4e23d-85bd-41b3-a320-3a510a1c2e7f'}], 'smp': '1', 'vmType': 'kvm', 'memSize': 512, 'displayIp': '0', 'spiceSecureChannels': 'smain,sinputs,scursor,splayback,srecord,sdisplay', 'smpCoresPerSocket': '1', 'vmName': 'fgjh', 'display': 'vnc', 'nice': '0'}} Thread-1429::DEBUG::2012-06-22 09:37:27,481::vm::568::vm.Vm::(_startUnderlyingVm) vmId=`92de99e5-067a-421b-a4b1-2a2b60e8894a`::_ongoingCreations acquired Thread-1429::INFO::2012-06-22 09:37:27,482::libvirtvm::1287::vm.Vm::(_run) vmId=`92de99e5-067a-421b-a4b1-2a2b60e8894a`::VM wrapper has started Thread-1429::DEBUG::2012-06-22 09:37:27,482::task::588::TaskManager.Task::(_updateState) Task=`5922124f-6997-4a7f-a3a8-b4852afabe18`::moving from state init -> state preparing Thread-1429::INFO::2012-06-22 09:37:27,482::logUtils::37::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='68aa0dc2-9cd1-4549-8008-30b1bae667db', spUUID='b1c7875a-964d-4633-8ea4-2b191d68c105', imgUUID='61180d3c-63ba-41ca-989a-8bd2acff4d7e', volUUID='eb866d5a-1319-4e32-b9f3-4de3ad3272fb', options=None) Thread-1429::DEBUG::2012-06-22 09:37:27,483::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.68aa0dc2-9cd1-4549-8008-30b1bae667db`ReqID=`2b25c825-b3b5-4 4f1-a41c-3e21dd2e716f`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource' Thread-1429::DEBUG::2012-06-22 09:37:27,483::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.68aa0dc2-9cd1-4549-8008-30b1bae667db' for lock type 'shared' Thread-1429::DEBUG::2012-06-22 09:37:27,483::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.68aa0dc2-9cd1-4549-8008-30b1bae667db' is free. Now locking as 'shared' (1 active user) Thread-1429::DEBUG::2012-06-22 09:37:27,483::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.68aa0dc2-9cd1-4549-8008-30b1bae667db`ReqID=`2b25c825-b3b5-4 4f1-a41c-3e21dd2e716f`::Granted request Thread-1429::DEBUG::2012-06-22 09:37:27,484::task::817::TaskManager.Task::(resourceAcquired) Task=`5922124f-6997-4a7f-a3a8-b4852afabe18`::_resourcesAcquired: Storage.68aa0dc2-9cd1-4549-8008-30b1bae667db (shared) Thread-1429::DEBUG::2012-06-22 09:37:27,484::task::978::TaskManager.Task::(_decref) Task=`5922124f-6997-4a7f-a3a8-b4852afabe18`::ref 1 aborting False Thread-1429::DEBUG::2012-06-22 09:37:27,485::fileVolume::535::Storage.Volume::(validateVolumePath) validate path for eb866d5a-1319-4e32-b9f3-4de3ad3272fb Thread-1429::DEBUG::2012-06-22 09:37:27,487::fileVolume::535::Storage.Volume::(validateVolumePath) validate path for eb866d5a-1319-4e32-b9f3-4de3ad3272fb Thread-1429::INFO::2012-06-22 09:37:27,488::logUtils::39::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '10737426432', 'apparentsize': '10737418240'} Thread-1429::DEBUG::2012-06-22 09:37:27,488::task::1172::TaskManager.Task::(prepare) Task=`5922124f-6997-4a7f-a3a8-b4852afabe18`::finished: {'truesize': '10737426432', 'apparentsize': '10737418240'} Thread-1429::DEBUG::2012-06-22 09:37:27,489::task::588::TaskManager.Task::(_updateState) Task=`5922124f-6997-4a7f-a3a8-b4852afabe18`::moving from state preparing -> state finished Thread-1429::DEBUG::2012-06-22 09:37:27,489::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.68aa0dc2-9cd1-4549-8008-30b1bae667db': < ResourceRef 'Storage.68aa0dc2-9cd1-4549-8008-30b1bae667db', isValid: 'True' obj: 'None'>} Thread-1429::DEBUG::2012-06-22 09:37:27,489::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-1429::DEBUG::2012-06-22 09:37:27,489::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.68aa0dc2-9cd1-4549-8008-30b1bae667db' Thread-1429::DEBUG::2012-06-22 09:37:27,489::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.68aa0dc2-9cd1-4549-8008-30b1bae667db' (0 active users) Thread-1429::DEBUG::2012-06-22 09:37:27,490::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.68aa0dc2-9cd1-4549-8008-30b1bae667db' is free, finding out if anyone is waiting for it. Thread-1429::DEBUG::2012-06-22 09:37:27,490::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.68aa0dc2-9cd1-4549-8008-30b1bae667db', Clearing records. Thread-1429::DEBUG::2012-06-22 09:37:27,490::task::978::TaskManager.Task::(_decref) Task=`5922124f-6997-4a7f-a3a8-b4852afabe18`::ref 0 aborting False Thread-1429::INFO::2012-06-22 09:37:27,490::clientIF::279::vds::(prepareVolumePath) prepared volume path: Thread-1429::DEBUG::2012-06-22 09:37:27,490::task::588::TaskManager.Task::(_updateState) Task=`9eba14b9-a037-4f59-bc90-97b5ce032503`::moving from state init -> state preparing Thread-1429::INFO::2012-06-22 09:37:27,491::logUtils::37::dispatcher::(wrapper) Run and protect: prepareImage(sdUUID='68aa0dc2-9cd1-4549-8008-30b1bae667db', spUUID='b1c7875a-964d-4633-8ea4-2b191d68c105', imgUUID='61180d3c-63ba-41ca-989a-8bd2acff4d7e', volUUID='eb866d5a-1319-4e32-b9f3-4de3ad3272fb') Thread-1429::DEBUG::2012-06-22 09:37:27,491::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.68aa0dc2-9cd1-4549-8008-30b1bae667db`ReqID=`95022af4-4bcc-4 503-81c6-767215c0cca5`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource' Thread-1429::DEBUG::2012-06-22 09:37:27,491::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.68aa0dc2-9cd1-4549-8008-30b1bae667db' for lock type 'shared' Thread-1429::DEBUG::2012-06-22 09:37:27,491::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.68aa0dc2-9cd1-4549-8008-30b1bae667db' is free. Now locking as 'shared' (1 active user) Thread-1429::DEBUG::2012-06-22 09:37:27,492::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.68aa0dc2-9cd1-4549-8008-30b1bae667db`ReqID=`95022af4-4bcc-4 503-81c6-767215c0cca5`::Granted request Thread-1429::DEBUG::2012-06-22 09:37:27,492::task::817::TaskManager.Task::(resourceAcquired) Task=`9eba14b9-a037-4f59-bc90-97b5ce032503`::_resourcesAcquired: Storage.68aa0dc2-9cd1-4549-8008-30b1bae667db (shared) Thread-1429::DEBUG::2012-06-22 09:37:27,492::task::978::TaskManager.Task::(_decref) Task=`9eba14b9-a037-4f59-bc90-97b5ce032503`::ref 1 aborting False Thread-1429::DEBUG::2012-06-22 09:37:27,493::fileVolume::535::Storage.Volume::(validateVolumePath) validate path for eb866d5a-1319-4e32-b9f3-4de3ad3272fb Thread-1429::INFO::2012-06-22 09:37:27,496::image::357::Storage.Image::(getChain) sdUUID=68aa0dc2-9cd1-4549-8008-30b1bae667db imgUUID=61180d3c-63ba-41ca-989a-8bd2acff4d7e chain=[<storage.fileVolume.FileVolume instance at 0x7fe5d4540ef0>] Thread-1429::INFO::2012-06-22 09:37:27,497::logUtils::39::dispatcher::(wrapper) Run and protect: prepareImage, Return response: {'path': '/rhev/data-center/b1c7875a-964d-4633-8ea4-2b191d68c105/68aa0dc2-9cd1-4549-8 008-30b1bae667db/images/61180d3c-63ba-41ca-989a-8bd2acff4d7e/eb866d5a-1319-4 e32-b9f3-4de3ad3272fb', 'chain': [{'path': '/rhev/data-center/b1c7875a-964d-4633-8ea4-2b191d68c105/68aa0dc2-9cd1-4549-8 008-30b1bae667db/images/61180d3c-63ba-41ca-989a-8bd2acff4d7e/eb866d5a-1319-4 e32-b9f3-4de3ad3272fb', 'domainID': '68aa0dc2-9cd1-4549-8008-30b1bae667db', 'volumeID': 'eb866d5a-1319-4e32-b9f3-4de3ad3272fb', 'imageID': '61180d3c-63ba-41ca-989a-8bd2acff4d7e'}]} Thread-1429::DEBUG::2012-06-22 09:37:27,498::task::1172::TaskManager.Task::(prepare) Task=`9eba14b9-a037-4f59-bc90-97b5ce032503`::finished: {'path': '/rhev/data-center/b1c7875a-964d-4633-8ea4-2b191d68c105/68aa0dc2-9cd1-4549-8 008-30b1bae667db/images/61180d3c-63ba-41ca-989a-8bd2acff4d7e/eb866d5a-1319-4 e32-b9f3-4de3ad3272fb', 'chain': [{'path': '/rhev/data-center/b1c7875a-964d-4633-8ea4-2b191d68c105/68aa0dc2-9cd1-4549-8 008-30b1bae667db/images/61180d3c-63ba-41ca-989a-8bd2acff4d7e/eb866d5a-1319-4 e32-b9f3-4de3ad3272fb', 'domainID': '68aa0dc2-9cd1-4549-8008-30b1bae667db', 'volumeID': 'eb866d5a-1319-4e32-b9f3-4de3ad3272fb', 'imageID': '61180d3c-63ba-41ca-989a-8bd2acff4d7e'}]} Thread-1429::DEBUG::2012-06-22 09:37:27,498::task::588::TaskManager.Task::(_updateState) Task=`9eba14b9-a037-4f59-bc90-97b5ce032503`::moving from state preparing -> state finished Thread-1429::DEBUG::2012-06-22 09:37:27,498::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.68aa0dc2-9cd1-4549-8008-30b1bae667db': < ResourceRef 'Storage.68aa0dc2-9cd1-4549-8008-30b1bae667db', isValid: 'True' obj: 'None'>} Thread-1429::DEBUG::2012-06-22 09:37:27,498::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-1429::DEBUG::2012-06-22 09:37:27,499::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.68aa0dc2-9cd1-4549-8008-30b1bae667db' Thread-1429::DEBUG::2012-06-22 09:37:27,499::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.68aa0dc2-9cd1-4549-8008-30b1bae667db' (0 active users) Thread-1429::DEBUG::2012-06-22 09:37:27,499::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.68aa0dc2-9cd1-4549-8008-30b1bae667db' is free, finding out if anyone is waiting for it. Thread-1429::DEBUG::2012-06-22 09:37:27,499::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.68aa0dc2-9cd1-4549-8008-30b1bae667db', Clearing records. Thread-1429::DEBUG::2012-06-22 09:37:27,500::task::978::TaskManager.Task::(_decref) Task=`9eba14b9-a037-4f59-bc90-97b5ce032503`::ref 0 aborting False Thread-1429::INFO::2012-06-22 09:37:27,500::clientIF::279::vds::(prepareVolumePath) prepared volume path: /rhev/data-center/b1c7875a-964d-4633-8ea4-2b191d68c105/68aa0dc2-9cd1-4549-80 08-30b1bae667db/images/61180d3c-63ba-41ca-989a-8bd2acff4d7e/eb866d5a-1319-4e 32-b9f3-4de3ad3272fb Thread-1429::DEBUG::2012-06-22 09:37:27,507::libvirtvm::1340::vm.Vm::(_run) vmId=`92de99e5-067a-421b-a4b1-2a2b60e8894a`::<?xml version="1.0" encoding="utf-8"?> <domain type="kvm"> <name>fgjh</name> <uuid>92de99e5-067a-421b-a4b1-2a2b60e8894a</uuid> <memory>524288</memory> <currentMemory>524288</currentMemory> <vcpu>1</vcpu> <devices> <channel type="unix"> <target name="com.redhat.rhevm.vdsm" type="virtio"/> <source mode="bind" path="/var/lib/libvirt/qemu/channels/fgjh.com.redhat.rhevm.vdsm"/> </channel> <input bus="usb" type="tablet"/> <graphics autoport="yes" keymap="en-us" listen="0" passwd="*****" passwdValidTo="1970-01-01T00:00:01" port="-1" type="vnc"/> <console type="pty"> <target port="0" type="virtio"/> </console> <video> <model heads="1" type="qxl" vram="65536"/> </video> <interface type="bridge"> <mac address="00:1a:4a:01:14:00"/> <model type="virtio"/> <source bridge="ovirtmgmt"/> </interface> <memballoon model="virtio"/> <disk device="cdrom" snapshot="no" type="file"> <source file=""/> <target bus="ide" dev="hdc"/> <readonly/> <serial></serial> </disk> <disk device="disk" snapshot="no" type="file"> <source file="/rhev/data-center/b1c7875a-964d-4633-8ea4-2b191d68c105/68aa0dc2-9cd1-4 549-8008-30b1bae667db/images/61180d3c-63ba-41ca-989a-8bd2acff4d7e/eb866d5a-1 319-4e32-b9f3-4de3ad3272fb"/> <target bus="virtio" dev="vda"/> <serial>61180d3c-63ba-41ca-989a-8bd2acff4d7e</serial> <boot order="1"/> <driver cache="none" error_policy="stop" io="threads" name="qemu" type="raw"/> </disk> </devices> <os> <type arch="x86_64" machine="pc">hvm</type> <smbios mode="sysinfo"/> </os> <sysinfo type="smbios"> <system> <entry name="manufacturer">Red Hat</entry> <entry name="product">RHEV Hypervisor</entry> <entry name="version">6.2-1.1</entry> <entry name="serial">068FD200-06AF-7318-06AF-73180A8F5201_00:1c:c4:74:94:f0</entry> <entry name="uuid">92de99e5-067a-421b-a4b1-2a2b60e8894a</entry> </system> </sysinfo> <clock adjustment="0" offset="variable"> <timer name="rtc" tickpolicy="catchup"/> </clock> <features> <acpi/> </features> <cpu match="exact"> <model>Conroe</model> <topology cores="1" sockets="1" threads="1"/> </cpu> </domain> Thread-1429::DEBUG::2012-06-22 09:37:28,084::vm::580::vm.Vm::(_startUnderlyingVm) vmId=`92de99e5-067a-421b-a4b1-2a2b60e8894a`::_ongoingCreations released Thread-1429::ERROR::2012-06-22 09:37:28,084::vm::604::vm.Vm::(_startUnderlyingVm) vmId=`92de99e5-067a-421b-a4b1-2a2b60e8894a`::The vm start process failed Traceback (most recent call last): File "/usr/share/vdsm/vm.py", line 570, in _startUnderlyingVm self._run() File "/usr/share/vdsm/libvirtvm.py", line 1366, in _run self._connection.createXML(domxml, flags), File "/usr/lib64/python2.6/site-packages/vdsm/libvirtconnection.py", line 82, in wrapper ret = f(*args, **kwargs) File "/usr/lib64/python2.6/site-packages/libvirt.py", line 2087, in createXML if ret is None:raise libvirtError('virDomainCreateXML() failed', conn=self) libvirtError: internal error Process exited while reading console log output: char device redirected to /dev/pts/1 qemu-kvm: -drive file=/rhev/data-center/b1c7875a-964d-4633-8ea4-2b191d68c105/68aa0dc2-9cd1-45 49-8008-30b1bae667db/images/61180d3c-63ba-41ca-989a-8bd2acff4d7e/eb866d5a-13 19-4e32-b9f3-4de3ad3272fb,if=none,id=drive-virtio-disk0,format=raw,serial=61 180d3c-63ba-41ca-989a-8bd2acff4d7e,cache=none,werror=stop,rerror=stop,aio=th reads: could not open disk image /rhev/data-center/b1c7875a-964d-4633-8ea4-2b191d68c105/68aa0dc2-9cd1-4549-80 08-30b1bae667db/images/61180d3c-63ba-41ca-989a-8bd2acff4d7e/eb866d5a-1319-4e 32-b9f3-4de3ad3272fb: Permission denied Thread-1429::DEBUG::2012-06-22 09:37:28,087::vm::920::vm.Vm::(setDownStatus) vmId=`92de99e5-067a-421b-a4b1-2a2b60e8894a`::Changed state to Down: internal error Process exited while reading console log output: char device redirected to /dev/pts/1 qemu-kvm: -drive file=/rhev/data-center/b1c7875a-964d-4633-8ea4-2b191d68c105/68aa0dc2-9cd1-45 49-8008-30b1bae667db/images/61180d3c-63ba-41ca-989a-8bd2acff4d7e/eb866d5a-13 19-4e32-b9f3-4de3ad3272fb,if=none,id=drive-virtio-disk0,format=raw,serial=61 180d3c-63ba-41ca-989a-8bd2acff4d7e,cache=none,werror=stop,rerror=stop,aio=th reads: could not open disk image /rhev/data-center/b1c7875a-964d-4633-8ea4-2b191d68c105/68aa0dc2-9cd1-4549-80 08-30b1bae667db/images/61180d3c-63ba-41ca-989a-8bd2acff4d7e/eb866d5a-1319-4e 32-b9f3-4de3ad3272fb: Permission denied Thread-1432::DEBUG::2012-06-22 09:37:28,354::BindingXMLRPC::872::vds::(wrapper) client [10.1.20.2]::call vmGetStats with ('92de99e5-067a-421b-a4b1-2a2b60e8894a',) {} Thread-1432::DEBUG::2012-06-22 09:37:28,354::BindingXMLRPC::879::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Down', 'hash': '0', 'exitMessage': 'internal error Process exited while reading console log output: char device redirected to /dev/pts/1\nqemu-kvm: -drive file=/rhev/data-center/b1c7875a-964d-4633-8ea4-2b191d68c105/68aa0dc2-9cd1-45 49-8008-30b1bae667db/images/61180d3c-63ba-41ca-989a-8bd2acff4d7e/eb866d5a-13 19-4e32-b9f3-4de3ad3272fb,if=none,id=drive-virtio-disk0,format=raw,serial=61 180d3c-63ba-41ca-989a-8bd2acff4d7e,cache=none,werror=stop,rerror=stop,aio=th reads: could not open disk image /rhev/data-center/b1c7875a-964d-4633-8ea4-2b191d68c105/68aa0dc2-9cd1-4549-80 08-30b1bae667db/images/61180d3c-63ba-41ca-989a-8bd2acff4d7e/eb866d5a-1319-4e 32-b9f3-4de3ad3272fb: Permission denied\n', 'vmId': '92de99e5-067a-421b-a4b1-2a2b60e8894a', 'timeOffset': '0', 'exitCode': 1}]} Thread-1433::DEBUG::2012-06-22 09:37:28,366::BindingXMLRPC::872::vds::(wrapper) client [10.1.20.2]::call vmDestroy with ('92de99e5-067a-421b-a4b1-2a2b60e8894a',) {} Thread-1433::INFO::2012-06-22 09:37:28,366::API::319::vds::(destroy) vmContainerLock acquired by vm 92de99e5-067a-421b-a4b1-2a2b60e8894a Thread-1433::DEBUG::2012-06-22 09:37:28,366::libvirtvm::2088::vm.Vm::(destroy) vmId=`92de99e5-067a-421b-a4b1-2a2b60e8894a`::destroy Called Thread-1433::INFO::2012-06-22 09:37:28,366::libvirtvm::2042::vm.Vm::(releaseVm) vmId=`92de99e5-067a-421b-a4b1-2a2b60e8894a`::Release VM resources Thread-1433::WARNING::2012-06-22 09:37:28,366::vm::328::vm.Vm::(_set_lastStatus) vmId=`92de99e5-067a-421b-a4b1-2a2b60e8894a`::trying to set state to Powering down when already Down Thread-1433::DEBUG::2012-06-22 09:37:28,367::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/service ksmtuned retune' (cwd None) Thread-1433::DEBUG::2012-06-22 09:37:28,413::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0 Thread-1433::DEBUG::2012-06-22 09:37:28,414::task::588::TaskManager.Task::(_updateState) Task=`f042d1c3-5c18-4cb2-89d9-87d64a560922`::moving from state init -> state preparing Thread-1433::INFO::2012-06-22 09:37:28,415::logUtils::37::dispatcher::(wrapper) Run and protect: inappropriateDevices(thiefId='92de99e5-067a-421b-a4b1-2a2b60e8894a') Thread-1433::INFO::2012-06-22 09:37:28,418::logUtils::39::dispatcher::(wrapper) Run and protect: inappropriateDevices, Return response: None Thread-1433::DEBUG::2012-06-22 09:37:28,418::task::1172::TaskManager.Task::(prepare) Task=`f042d1c3-5c18-4cb2-89d9-87d64a560922`::finished: None Thread-1433::DEBUG::2012-06-22 09:37:28,418::task::588::TaskManager.Task::(_updateState) Task=`f042d1c3-5c18-4cb2-89d9-87d64a560922`::moving from state preparing -> state finished Thread-1433::DEBUG::2012-06-22 09:37:28,419::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-1433::DEBUG::2012-06-22 09:37:28,419::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-1433::DEBUG::2012-06-22 09:37:28,419::task::978::TaskManager.Task::(_decref) Task=`f042d1c3-5c18-4cb2-89d9-87d64a560922`::ref 0 aborting False Thread-1433::DEBUG::2012-06-22 09:37:28,419::libvirtvm::2083::vm.Vm::(deleteVm) vmId=`92de99e5-067a-421b-a4b1-2a2b60e8894a`::Total desktops after destroy of 92de99e5-067a-421b-a4b1-2a2b60e8894a is 0 Thread-1433::DEBUG::2012-06-22 09:37:28,420::BindingXMLRPC::879::vds::(wrapper) return vmDestroy with {'status': {'message': 'Machine destroyed', 'code': 0}} Thread-1434::DEBUG::2012-06-22 09:37:30,459::task::588::TaskManager.Task::(_updateState) Task=`a479829e-33ba-4c9b-987a-bc61d8bf11d6`::moving from state init -> state preparing Thread-1434::INFO::2012-06-22 09:37:30,459::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None) Thread-1434::INFO::2012-06-22 09:37:30,459::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'68aa0dc2-9cd1-4549-8008-30b1bae667db': {'delay': '0.0014181137085', 'lastCheck': 1340372243.5057499, 'code': 0, 'valid': True}} Thread-1434::DEBUG::2012-06-22 09:37:30,460::task::1172::TaskManager.Task::(prepare) Task=`a479829e-33ba-4c9b-987a-bc61d8bf11d6`::finished: {'68aa0dc2-9cd1-4549-8008-30b1bae667db': {'delay': '0.0014181137085', 'lastCheck': 1340372243.5057499, 'code': 0, 'valid': True}} Thread-1434::DEBUG::2012-06-22 09:37:30,460::task::588::TaskManager.Task::(_updateState) Task=`a479829e-33ba-4c9b-987a-bc61d8bf11d6`::moving from state preparing -> state finished Thread-1434::DEBUG::2012-06-22 09:37:30,460::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-1434::DEBUG::2012-06-22 09:37:30,460::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-1434::DEBUG::2012-06-22 09:37:30,460::task::978::TaskManager.Task::(_decref) Task=`a479829e-33ba-4c9b-987a-bc61d8bf11d6`::ref 0 aborting False ^C Error: libvirtError: internal error Process exited while reading console log output: char device redirected to /dev/pts/1 qemu-kvm: -drive file=/rhev/data-center/b1c7875a-964d-4633-8ea4-2b191d68c105/68aa0dc2-9cd1-45 49-8008-30b1bae667db/images/61180d3c-63ba-41ca-989a-8bd2acff4d7e/eb866d5a-13 19-4e32-b9f3-4de3ad3272fb,if=none,id=drive-virtio-disk0,format=raw,serial=61 180d3c-63ba-41ca-989a-8bd2acff4d7e,cache=none,werror=stop,rerror=stop,aio=th reads: could not open disk image /rhev/data-center/b1c7875a-964d-4633-8ea4-2b191d68c105/68aa0dc2-9cd1-4549-80 08-30b1bae667db/images/61180d3c-63ba-41ca-989a-8bd2acff4d7e/eb866d5a-1319-4e 32-b9f3-4de3ad3272fb: Permission denied [root@noc-3-synt mnt]# ls -lh /rhev/data-center/b1c7875a-964d-4633-8ea4-2b191d68c105/68aa0dc2-9cd1-4549-80 08-30b1bae667db/images/61180d3c-63ba-41ca-989a-8bd2acff4d7e/eb866d5a-1319-4e 32-b9f3-4de3ad3272fb -rw-rw----. 1 vdsm kvm 10G Jun 22 09:28 /rhev/data-center/b1c7875a-964d-4633-8ea4-2b191d68c105/68aa0dc2-9cd1-4549-80 08-30b1bae667db/images/61180d3c-63ba-41ca-989a-8bd2acff4d7e/eb866d5a-1319-4e 32-b9f3-4de3ad3272fb [root@noc-3-synt mnt]# ps -aux | grep /usr/share/vdsm/vdsm Warning: bad syntax, perhaps a bogus '-'? See /usr/share/doc/procps-3.2.8/FAQ root 2761 0.0 0.0 103280 804 pts/0 S+ 09:51 0:00 grep /usr/share/vdsm/vdsm vdsm 4480 0.0 0.0 9272 616 ? S< 09:07 0:00 /bin/bash -e /usr/share/vdsm/respawn --minlifetime 10 --daemon --masterpid /var/run/vdsm/respawn.pid /usr/share/vdsm/vdsm vdsm 4483 0.6 0.2 1411684 34800 ? S<l 09:07 0:17 /usr/bin/python /usr/share/vdsm/vdsm vdsm 5265 0.0 0.1 1387096 26880 ? S< 09:17 0:00 /usr/bin/python /usr/share/vdsm/vdsm vdsm 5266 0.0 0.1 1387096 26660 ? S< 09:17 0:00 /usr/bin/python /usr/share/vdsm/vdsm vdsm 5267 0.0 0.1 1387096 26660 ? S< 09:17 0:00 /usr/bin/python /usr/share/vdsm/vdsm vdsm 5269 0.0 0.1 1387096 26584 ? S< 09:17 0:00 /usr/bin/python /usr/share/vdsm/vdsm vdsm 5271 0.0 0.1 1387096 26584 ? S< 09:17 0:00 /usr/bin/python /usr/share/vdsm/vdsm :. ------=_NextPart_000_00B5_01CD50A1.2C0D2C70 Content-Type: text/html; charset="koi8-r" Content-Transfer-Encoding: quoted-printable <html xmlns:v=3D"urn:schemas-microsoft-com:vml" = xmlns:o=3D"urn:schemas-microsoft-com:office:office" = xmlns:w=3D"urn:schemas-microsoft-com:office:word" = xmlns:m=3D"http://schemas.microsoft.com/office/2004/12/omml" = xmlns=3D"http://www.w3.org/TR/REC-html40"><head> <META HTTP-EQUIV=3D"Content-Type" CONTENT=3D"text/html; = charset=3Dkoi8-r"> <meta name=3DGenerator content=3D"Microsoft Word 12 (filtered = medium)"><style></style></head><body lang=3DRU link=3Dblue = vlink=3Dpurple><div class=3DWordSection1>Hi.<o:p></o:p>I use a bunch of ovirt 3.1 beta and gluster storage. = <o:p></o:p>The = virtual machine was created successfully, but will not = start.<o:p></o:p><o:p> </o:p>In the logs:<o:p></o:p>Vdsm.log:<o:p></o:p>Thread-1426::DEBUG::2012-06-22 = 09:37:27,151::task::978::TaskManager.Task::(_decref) = Task=3D`9a68c120-169f-4c0e-98e3-08e3bf5c66ab`::ref 0 aborting = False<o:p></o:p>Thread-1427::DEBUG::2012-06-22 = 09:37:27,162::BindingXMLRPC::160::vds::(wrapper) = [10.1.20.2]<o:p></o:p>Thread-1427::DEBUG::2012-06-22 = 09:37:27,163::task::588::TaskManager.Task::(_updateState) = Task=3D`662a52dd-f00d-4be1-941d-eac8ec6a70f6`::moving from state init = -> state preparing<o:p></o:p>Thread-1427::INFO::2012-06-22 = 09:37:27,163::logUtils::37::dispatcher::(wrapper) Run and protect: = getStoragePoolInfo(spUUID=3D'b1c7875a-964d-4633-8ea4-2b191d68c105', = options=3DNone)<o:p></o:p>Thread-1427::DEBUG::2012-06-22 = 09:37:27,163::resourceManager::175::ResourceManager.Request::(__init__) = ResName=3D`Storage.b1c7875a-964d-4633-8ea4-2b191d68c105`ReqID=3D`ca9b7715= -1f0b-4225-9717-d1179193c42e`::Request was made in = '/usr/share/vdsm/storage/resourceManager.py' line '485' at = 'registerResource'<o:p></o:p>Thread-1427::DEBUG::2012-06-22 = 09:37:27,164::resourceManager::486::ResourceManager::(registerResource) = Trying to register resource = 'Storage.b1c7875a-964d-4633-8ea4-2b191d68c105' for lock type = 'shared'<o:p></o:p>Thread-1427::DEBUG::2012-06-22 = 09:37:27,164::resourceManager::528::ResourceManager::(registerResource) = Resource 'Storage.b1c7875a-964d-4633-8ea4-2b191d68c105' is free. Now = locking as 'shared' (1 active user)<o:p></o:p>Thread-1427::DEBUG::2012-06-22 = 09:37:27,164::resourceManager::212::ResourceManager.Request::(grant) = ResName=3D`Storage.b1c7875a-964d-4633-8ea4-2b191d68c105`ReqID=3D`ca9b7715= -1f0b-4225-9717-d1179193c42e`::Granted request<o:p></o:p>Thread-1427::DEBUG::2012-06-22 = 09:37:27,164::task::817::TaskManager.Task::(resourceAcquired) = Task=3D`662a52dd-f00d-4be1-941d-eac8ec6a70f6`::_resourcesAcquired: = Storage.b1c7875a-964d-4633-8ea4-2b191d68c105 = (shared)<o:p></o:p>Thread-1427::DEBUG::2012-06-22 = 09:37:27,165::task::978::TaskManager.Task::(_decref) = Task=3D`662a52dd-f00d-4be1-941d-eac8ec6a70f6`::ref 1 aborting = False<o:p></o:p>Thread-1427::INFO::2012-06-22 = 09:37:27,165::logUtils::39::dispatcher::(wrapper) Run and protect: = getStoragePoolInfo, Return response: {'info': {'spm_id': 1, = 'master_uuid': '68aa0dc2-9cd1-4549-8008-30b1bae667db', 'name': = 'gluster', 'version': '0', 'domains': = '68aa0dc2-9cd1-4549-8008-30b1bae667db:Active', 'pool_status': = 'connected', 'isoprefix': '', 'type': 'SHAREDFS', 'master_ver': 1, = 'lver': 0}, 'dominfo': {'68aa0dc2-9cd1-4549-8008-30b1bae667db': = {'status': 'Active', 'diskfree': '27505983488', 'alerts': [], = 'disktotal': '53579874304'}}}<o:p></o:p>Thread-1427::DEBUG::2012-06-22 = 09:37:27,165::task::1172::TaskManager.Task::(prepare) = Task=3D`662a52dd-f00d-4be1-941d-eac8ec6a70f6`::finished: {'info': = {'spm_id': 1, 'master_uuid': '68aa0dc2-9cd1-4549-8008-30b1bae667db', = 'name': 'gluster', 'version': '0', 'domains': = '68aa0dc2-9cd1-4549-8008-30b1bae667db:Active', 'pool_status': = 'connected', 'isoprefix': '', 'type': 'SHAREDFS', 'master_ver': 1, = 'lver': 0}, 'dominfo': {'68aa0dc2-9cd1-4549-8008-30b1bae667db': = {'status': 'Active', 'diskfree': '27505983488', 'alerts': [], = 'disktotal': '53579874304'}}}<o:p></o:p>Thread-1427::DEBUG::2012-06-22 = 09:37:27,166::task::588::TaskManager.Task::(_updateState) = Task=3D`662a52dd-f00d-4be1-941d-eac8ec6a70f6`::moving from state = preparing -> state finished<o:p></o:p>Thread-1427::DEBUG::2012-06-22 = 09:37:27,166::resourceManager::809::ResourceManager.Owner::(releaseAll) = Owner.releaseAll requests {} resources = {'Storage.b1c7875a-964d-4633-8ea4-2b191d68c105': < ResourceRef = 'Storage.b1c7875a-964d-4633-8ea4-2b191d68c105', isValid: 'True' obj: = 'None'>}<o:p></o:p>Thread-1427::DEBUG::2012-06-22 = 09:37:27,166::resourceManager::844::ResourceManager.Owner::(cancelAll) = Owner.cancelAll requests {}<o:p></o:p>Thread-1427::DEBUG::2012-06-22 = 09:37:27,166::resourceManager::538::ResourceManager::(releaseResource) = Trying to release resource = 'Storage.b1c7875a-964d-4633-8ea4-2b191d68c105'<o:p></o:p>Thread-1427::DEBUG::2012-06-22 = 09:37:27,166::resourceManager::553::ResourceManager::(releaseResource) = Released resource 'Storage.b1c7875a-964d-4633-8ea4-2b191d68c105' (0 = active users)<o:p></o:p>Thread-1427::DEBUG::2012-06-22 = 09:37:27,167::resourceManager::558::ResourceManager::(releaseResource) = Resource 'Storage.b1c7875a-964d-4633-8ea4-2b191d68c105' is free, finding = out if anyone is waiting for it.<o:p></o:p>Thread-1427::DEBUG::2012-06-22 = 09:37:27,167::resourceManager::565::ResourceManager::(releaseResource) = No one is waiting for resource = 'Storage.b1c7875a-964d-4633-8ea4-2b191d68c105', Clearing = records.<o:p></o:p>Thread-1427::DEBUG::2012-06-22 = 09:37:27,167::task::978::TaskManager.Task::(_decref) = Task=3D`662a52dd-f00d-4be1-941d-eac8ec6a70f6`::ref 0 aborting = False<o:p></o:p>Thread-1428::DEBUG::2012-06-22 = 09:37:27,476::BindingXMLRPC::872::vds::(wrapper) client = [10.1.20.2]::call vmCreate with ({'custom': {}, 'keyboardLayout': = 'en-us', 'kvmEnable': 'true', 'acpiEnable': 'true', 'emulatedMachine': = 'pc', 'tabletEnable': 'true', 'vmId': = '92de99e5-067a-421b-a4b1-2a2b60e8894a', 'devices': [{'device': 'qxl', = 'specParams': {'vram': '65536'}, 'type': 'video', 'deviceId': = '9780f3aa-4c0e-44eb-bc94-7ebfb63fe2f3'}, {'index': '2', 'iface': 'ide', = 'specParams': {'path': ''}, 'readonly': 'true', 'deviceId': = '59b3e477-8ba9-4a09-ac4a-4d0da91708ce', 'device': 'cdrom', 'path': '', = 'type': 'disk'}, {'index': 0, 'iface': 'virtio', 'format': 'raw', = 'bootOrder': '1', 'volumeID': 'eb866d5a-1319-4e32-b9f3-4de3ad3272fb', = 'imageID': '61180d3c-63ba-41ca-989a-8bd2acff4d7e', 'specParams': {}, = 'readonly': 'false', 'domainID': '68aa0dc2-9cd1-4549-8008-30b1bae667db', = 'optional': 'false', 'deviceId': '61180d3c-63ba-41ca-989a-8bd2acff4d7e', = 'poolID': 'b1c7875a-964d-4633-8ea4-2b191d68c105', 'device': 'disk', = 'shared': 'false', 'propagateErrors': 'off', 'type': 'disk'}, = {'nicModel': 'pv', 'macAddr': '00:1a:4a:01:14:00', 'network': = 'ovirtmgmt', 'specParams': {}, 'deviceId': = 'c580b531-2178-4a38-bb1e-971bf300bf8a', 'device': 'bridge', 'type': = 'interface'}, {'device': 'memballoon', 'specParams': {'model': = 'virtio'}, 'type': 'balloon', 'deviceId': = '3df4e23d-85bd-41b3-a320-3a510a1c2e7f'}], 'smp': '1', 'vmType': 'kvm', = 'timeOffset': '0', 'memSize': 512, 'spiceSslCipherSuite': 'DEFAULT', = 'cpuType': 'Conroe', 'spiceSecureChannels': = 'smain,sinputs,scursor,splayback,srecord,sdisplay', 'smpCoresPerSocket': = '1', 'vmName': 'fgjh', 'display': 'vnc', 'transparentHugePages': 'true', = 'nice': '0'},) {} flowID [60053096]<o:p></o:p>Thread-1428::INFO::2012-06-22 = 09:37:27,477::API::603::vds::(_getNetworkIp) network None: using = 0<o:p></o:p>Thread-1428::INFO::2012-06-22 = 09:37:27,477::API::229::vds::(create) vmContainerLock acquired by vm = 92de99e5-067a-421b-a4b1-2a2b60e8894a<o:p></o:p>Thread-1429::DEBUG::2012-06-22 = 09:37:27,479::vm::564::vm.Vm::(_startUnderlyingVm) = vmId=3D`92de99e5-067a-421b-a4b1-2a2b60e8894a`::Start<o:p></o:p></p= >Thread-1428::DEBUG::2012-06-22 = 09:37:27,479::API::246::vds::(create) Total desktops after creation of = 92de99e5-067a-421b-a4b1-2a2b60e8894a is 1<o:p></o:p>Thread-1428::DEBUG::2012-06-22 = 09:37:27,480::BindingXMLRPC::879::vds::(wrapper) return vmCreate with = {'status': {'message': 'Done', 'code': 0}, 'vmList': {'status': = 'WaitForLaunch', 'acpiEnable': 'true', 'emulatedMachine': 'pc', = 'tabletEnable': 'true', 'pid': '0', 'timeOffset': '0', 'displayPort': = '-1', 'displaySecurePort': '-1', 'spiceSslCipherSuite': 'DEFAULT', = 'cpuType': 'Conroe', 'custom': {}, 'clientIp': '', 'nicModel': = 'rtl8139,pv', 'keyboardLayout': 'en-us', 'kvmEnable': 'true', 'vmId': = '92de99e5-067a-421b-a4b1-2a2b60e8894a', 'transparentHugePages': 'true', = 'devices': [{'device': 'qxl', 'specParams': {'vram': '65536'}, 'type': = 'video', 'deviceId': '9780f3aa-4c0e-44eb-bc94-7ebfb63fe2f3'}, {'index': = '2', 'iface': 'ide', 'specParams': {'path': ''}, 'readonly': 'true', = 'deviceId': '59b3e477-8ba9-4a09-ac4a-4d0da91708ce', 'device': 'cdrom', = 'path': '', 'type': 'disk'}, {'index': 0, 'iface': 'virtio', 'format': = 'raw', 'bootOrder': '1', 'volumeID': = 'eb866d5a-1319-4e32-b9f3-4de3ad3272fb', 'imageID': = '61180d3c-63ba-41ca-989a-8bd2acff4d7e', 'specParams': {}, 'readonly': = 'false', 'domainID': '68aa0dc2-9cd1-4549-8008-30b1bae667db', 'optional': = 'false', 'deviceId': '61180d3c-63ba-41ca-989a-8bd2acff4d7e', 'poolID': = 'b1c7875a-964d-4633-8ea4-2b191d68c105', 'device': 'disk', 'shared': = 'false', 'propagateErrors': 'off', 'type': 'disk'}, {'nicModel': 'pv', = 'macAddr': '00:1a:4a:01:14:00', 'network': 'ovirtmgmt', 'specParams': = {}, 'deviceId': 'c580b531-2178-4a38-bb1e-971bf300bf8a', 'device': = 'bridge', 'type': 'interface'}, {'device': 'memballoon', 'specParams': = {'model': 'virtio'}, 'type': 'balloon', 'deviceId': = '3df4e23d-85bd-41b3-a320-3a510a1c2e7f'}], 'smp': '1', 'vmType': 'kvm', = 'memSize': 512, 'displayIp': '0', 'spiceSecureChannels': = 'smain,sinputs,scursor,splayback,srecord,sdisplay', 'smpCoresPerSocket': = '1', 'vmName': 'fgjh', 'display': 'vnc', 'nice': = '0'}}<o:p></o:p>Thread-1429::DEBUG::2012-06-22 = 09:37:27,481::vm::568::vm.Vm::(_startUnderlyingVm) = vmId=3D`92de99e5-067a-421b-a4b1-2a2b60e8894a`::_ongoingCreations = acquired<o:p></o:p>Thread-1429::INFO::2012-06-22 = 09:37:27,482::libvirtvm::1287::vm.Vm::(_run) = vmId=3D`92de99e5-067a-421b-a4b1-2a2b60e8894a`::VM wrapper has = started<o:p></o:p>Thread-1429::DEBUG::2012-06-22 = 09:37:27,482::task::588::TaskManager.Task::(_updateState) = Task=3D`5922124f-6997-4a7f-a3a8-b4852afabe18`::moving from state init = -> state preparing<o:p></o:p>Thread-1429::INFO::2012-06-22 = 09:37:27,482::logUtils::37::dispatcher::(wrapper) Run and protect: = getVolumeSize(sdUUID=3D'68aa0dc2-9cd1-4549-8008-30b1bae667db', = spUUID=3D'b1c7875a-964d-4633-8ea4-2b191d68c105', = imgUUID=3D'61180d3c-63ba-41ca-989a-8bd2acff4d7e', = volUUID=3D'eb866d5a-1319-4e32-b9f3-4de3ad3272fb', = options=3DNone)<o:p></o:p>Thread-1429::DEBUG::2012-06-22 = 09:37:27,483::resourceManager::175::ResourceManager.Request::(__init__) = ResName=3D`Storage.68aa0dc2-9cd1-4549-8008-30b1bae667db`ReqID=3D`2b25c825= -b3b5-44f1-a41c-3e21dd2e716f`::Request was made in = '/usr/share/vdsm/storage/resourceManager.py' line '485' at = 'registerResource'<o:p></o:p>Thread-1429::DEBUG::2012-06-22 = 09:37:27,483::resourceManager::486::ResourceManager::(registerResource) = Trying to register resource = 'Storage.68aa0dc2-9cd1-4549-8008-30b1bae667db' for lock type = 'shared'<o:p></o:p>Thread-1429::DEBUG::2012-06-22 = 09:37:27,483::resourceManager::528::ResourceManager::(registerResource) = Resource 'Storage.68aa0dc2-9cd1-4549-8008-30b1bae667db' is free. Now = locking as 'shared' (1 active user)<o:p></o:p>Thread-1429::DEBUG::2012-06-22 = 09:37:27,483::resourceManager::212::ResourceManager.Request::(grant) = ResName=3D`Storage.68aa0dc2-9cd1-4549-8008-30b1bae667db`ReqID=3D`2b25c825= -b3b5-44f1-a41c-3e21dd2e716f`::Granted request<o:p></o:p>Thread-1429::DEBUG::2012-06-22 = 09:37:27,484::task::817::TaskManager.Task::(resourceAcquired) = Task=3D`5922124f-6997-4a7f-a3a8-b4852afabe18`::_resourcesAcquired: = Storage.68aa0dc2-9cd1-4549-8008-30b1bae667db = (shared)<o:p></o:p>Thread-1429::DEBUG::2012-06-22 = 09:37:27,484::task::978::TaskManager.Task::(_decref) = Task=3D`5922124f-6997-4a7f-a3a8-b4852afabe18`::ref 1 aborting = False<o:p></o:p>Thread-1429::DEBUG::2012-06-22 = 09:37:27,485::fileVolume::535::Storage.Volume::(validateVolumePath) = validate path for = eb866d5a-1319-4e32-b9f3-4de3ad3272fb<o:p></o:p>Thread-1429::DEBUG::2012-06-22 = 09:37:27,487::fileVolume::535::Storage.Volume::(validateVolumePath) = validate path for = eb866d5a-1319-4e32-b9f3-4de3ad3272fb<o:p></o:p>Thread-1429::INFO::2012-06-22 = 09:37:27,488::logUtils::39::dispatcher::(wrapper) Run and protect: = getVolumeSize, Return response: {'truesize': '10737426432', = 'apparentsize': '10737418240'}<o:p></o:p>Thread-1429::DEBUG::2012-06-22 = 09:37:27,488::task::1172::TaskManager.Task::(prepare) = Task=3D`5922124f-6997-4a7f-a3a8-b4852afabe18`::finished: {'truesize': = '10737426432', 'apparentsize': '10737418240'}<o:p></o:p>Thread-1429::DEBUG::2012-06-22 = 09:37:27,489::task::588::TaskManager.Task::(_updateState) = Task=3D`5922124f-6997-4a7f-a3a8-b4852afabe18`::moving from state = preparing -> state finished<o:p></o:p>Thread-1429::DEBUG::2012-06-22 = 09:37:27,489::resourceManager::809::ResourceManager.Owner::(releaseAll) = Owner.releaseAll requests {} resources = {'Storage.68aa0dc2-9cd1-4549-8008-30b1bae667db': < ResourceRef = 'Storage.68aa0dc2-9cd1-4549-8008-30b1bae667db', isValid: 'True' obj: = 'None'>}<o:p></o:p>Thread-1429::DEBUG::2012-06-22 = 09:37:27,489::resourceManager::844::ResourceManager.Owner::(cancelAll) = Owner.cancelAll requests {}<o:p></o:p>Thread-1429::DEBUG::2012-06-22 = 09:37:27,489::resourceManager::538::ResourceManager::(releaseResource) = Trying to release resource = 'Storage.68aa0dc2-9cd1-4549-8008-30b1bae667db'<o:p></o:p>Thread-1429::DEBUG::2012-06-22 = 09:37:27,489::resourceManager::553::ResourceManager::(releaseResource) = Released resource 'Storage.68aa0dc2-9cd1-4549-8008-30b1bae667db' (0 = active users)<o:p></o:p>Thread-1429::DEBUG::2012-06-22 = 09:37:27,490::resourceManager::558::ResourceManager::(releaseResource) = Resource 'Storage.68aa0dc2-9cd1-4549-8008-30b1bae667db' is free, finding = out if anyone is waiting for it.<o:p></o:p>Thread-1429::DEBUG::2012-06-22 = 09:37:27,490::resourceManager::565::ResourceManager::(releaseResource) = No one is waiting for resource = 'Storage.68aa0dc2-9cd1-4549-8008-30b1bae667db', Clearing = records.<o:p></o:p>Thread-1429::DEBUG::2012-06-22 = 09:37:27,490::task::978::TaskManager.Task::(_decref) = Task=3D`5922124f-6997-4a7f-a3a8-b4852afabe18`::ref 0 aborting = False<o:p></o:p>Thread-1429::INFO::2012-06-22 = 09:37:27,490::clientIF::279::vds::(prepareVolumePath) prepared volume = path:<o:p></o:p>Thread-1429::DEBUG::2012-06-22 = 09:37:27,490::task::588::TaskManager.Task::(_updateState) = Task=3D`9eba14b9-a037-4f59-bc90-97b5ce032503`::moving from state init = -> state preparing<o:p></o:p>Thread-1429::INFO::2012-06-22 = 09:37:27,491::logUtils::37::dispatcher::(wrapper) Run and protect: = prepareImage(sdUUID=3D'68aa0dc2-9cd1-4549-8008-30b1bae667db', = spUUID=3D'b1c7875a-964d-4633-8ea4-2b191d68c105', = imgUUID=3D'61180d3c-63ba-41ca-989a-8bd2acff4d7e', = volUUID=3D'eb866d5a-1319-4e32-b9f3-4de3ad3272fb')<o:p></o:p><p= class=3DMsoNormal>Thread-1429::DEBUG::2012-06-22 = 09:37:27,491::resourceManager::175::ResourceManager.Request::(__init__) = ResName=3D`Storage.68aa0dc2-9cd1-4549-8008-30b1bae667db`ReqID=3D`95022af4= -4bcc-4503-81c6-767215c0cca5`::Request was made in = '/usr/share/vdsm/storage/resourceManager.py' line '485' at = 'registerResource'<o:p></o:p>Thread-1429::DEBUG::2012-06-22 = 09:37:27,491::resourceManager::486::ResourceManager::(registerResource) = Trying to register resource = 'Storage.68aa0dc2-9cd1-4549-8008-30b1bae667db' for lock type = 'shared'<o:p></o:p>Thread-1429::DEBUG::2012-06-22 = 09:37:27,491::resourceManager::528::ResourceManager::(registerResource) = Resource 'Storage.68aa0dc2-9cd1-4549-8008-30b1bae667db' is free. Now = locking as 'shared' (1 active user)<o:p></o:p>Thread-1429::DEBUG::2012-06-22 = 09:37:27,492::resourceManager::212::ResourceManager.Request::(grant) = ResName=3D`Storage.68aa0dc2-9cd1-4549-8008-30b1bae667db`ReqID=3D`95022af4= -4bcc-4503-81c6-767215c0cca5`::Granted request<o:p></o:p>Thread-1429::DEBUG::2012-06-22 = 09:37:27,492::task::817::TaskManager.Task::(resourceAcquired) = Task=3D`9eba14b9-a037-4f59-bc90-97b5ce032503`::_resourcesAcquired: = Storage.68aa0dc2-9cd1-4549-8008-30b1bae667db = (shared)<o:p></o:p>Thread-1429::DEBUG::2012-06-22 = 09:37:27,492::task::978::TaskManager.Task::(_decref) = Task=3D`9eba14b9-a037-4f59-bc90-97b5ce032503`::ref 1 aborting = False<o:p></o:p>Thread-1429::DEBUG::2012-06-22 = 09:37:27,493::fileVolume::535::Storage.Volume::(validateVolumePath) = validate path for = eb866d5a-1319-4e32-b9f3-4de3ad3272fb<o:p></o:p>Thread-1429::INFO::2012-06-22 = 09:37:27,496::image::357::Storage.Image::(getChain) = sdUUID=3D68aa0dc2-9cd1-4549-8008-30b1bae667db = imgUUID=3D61180d3c-63ba-41ca-989a-8bd2acff4d7e = chain=3D[<storage.fileVolume.FileVolume instance at = 0x7fe5d4540ef0>]<o:p></o:p>Thread-1429::INFO::2012-06-22 = 09:37:27,497::logUtils::39::dispatcher::(wrapper) Run and protect: = prepareImage, Return response: {'path': = '/rhev/data-center/b1c7875a-964d-4633-8ea4-2b191d68c105/68aa0dc2-9cd1-454= 9-8008-30b1bae667db/images/61180d3c-63ba-41ca-989a-8bd2acff4d7e/eb866d5a-= 1319-4e32-b9f3-4de3ad3272fb', 'chain': [{'path': = '/rhev/data-center/b1c7875a-964d-4633-8ea4-2b191d68c105/68aa0dc2-9cd1-454= 9-8008-30b1bae667db/images/61180d3c-63ba-41ca-989a-8bd2acff4d7e/eb866d5a-= 1319-4e32-b9f3-4de3ad3272fb', 'domainID': = '68aa0dc2-9cd1-4549-8008-30b1bae667db', 'volumeID': = 'eb866d5a-1319-4e32-b9f3-4de3ad3272fb', 'imageID': = '61180d3c-63ba-41ca-989a-8bd2acff4d7e'}]}<o:p></o:p>Thread-1429::DEBUG::2012-06-22 = 09:37:27,498::task::1172::TaskManager.Task::(prepare) = Task=3D`9eba14b9-a037-4f59-bc90-97b5ce032503`::finished: {'path': = '/rhev/data-center/b1c7875a-964d-4633-8ea4-2b191d68c105/68aa0dc2-9cd1-454= 9-8008-30b1bae667db/images/61180d3c-63ba-41ca-989a-8bd2acff4d7e/eb866d5a-= 1319-4e32-b9f3-4de3ad3272fb', 'chain': [{'path': = '/rhev/data-center/b1c7875a-964d-4633-8ea4-2b191d68c105/68aa0dc2-9cd1-454= 9-8008-30b1bae667db/images/61180d3c-63ba-41ca-989a-8bd2acff4d7e/eb866d5a-= 1319-4e32-b9f3-4de3ad3272fb', 'domainID': = '68aa0dc2-9cd1-4549-8008-30b1bae667db', 'volumeID': = 'eb866d5a-1319-4e32-b9f3-4de3ad3272fb', 'imageID': = '61180d3c-63ba-41ca-989a-8bd2acff4d7e'}]}<o:p></o:p>Thread-1429::DEBUG::2012-06-22 = 09:37:27,498::task::588::TaskManager.Task::(_updateState) = Task=3D`9eba14b9-a037-4f59-bc90-97b5ce032503`::moving from state = preparing -> state finished<o:p></o:p>Thread-1429::DEBUG::2012-06-22 = 09:37:27,498::resourceManager::809::ResourceManager.Owner::(releaseAll) = Owner.releaseAll requests {} resources = {'Storage.68aa0dc2-9cd1-4549-8008-30b1bae667db': < ResourceRef = 'Storage.68aa0dc2-9cd1-4549-8008-30b1bae667db', isValid: 'True' obj: = 'None'>}<o:p></o:p>Thread-1429::DEBUG::2012-06-22 = 09:37:27,498::resourceManager::844::ResourceManager.Owner::(cancelAll) = Owner.cancelAll requests {}<o:p></o:p>Thread-1429::DEBUG::2012-06-22 = 09:37:27,499::resourceManager::538::ResourceManager::(releaseResource) = Trying to release resource = 'Storage.68aa0dc2-9cd1-4549-8008-30b1bae667db'<o:p></o:p>Thread-1429::DEBUG::2012-06-22 = 09:37:27,499::resourceManager::553::ResourceManager::(releaseResource) = Released resource 'Storage.68aa0dc2-9cd1-4549-8008-30b1bae667db' (0 = active users)<o:p></o:p>Thread-1429::DEBUG::2012-06-22 = 09:37:27,499::resourceManager::558::ResourceManager::(releaseResource) = Resource 'Storage.68aa0dc2-9cd1-4549-8008-30b1bae667db' is free, finding = out if anyone is waiting for it.<o:p></o:p>Thread-1429::DEBUG::2012-06-22 = 09:37:27,499::resourceManager::565::ResourceManager::(releaseResource) = No one is waiting for resource = 'Storage.68aa0dc2-9cd1-4549-8008-30b1bae667db', Clearing = records.<o:p></o:p>Thread-1429::DEBUG::2012-06-22 = 09:37:27,500::task::978::TaskManager.Task::(_decref) = Task=3D`9eba14b9-a037-4f59-bc90-97b5ce032503`::ref 0 aborting = False<o:p></o:p>Thread-1429::INFO::2012-06-22 = 09:37:27,500::clientIF::279::vds::(prepareVolumePath) prepared volume = path: = /rhev/data-center/b1c7875a-964d-4633-8ea4-2b191d68c105/68aa0dc2-9cd1-4549= -8008-30b1bae667db/images/61180d3c-63ba-41ca-989a-8bd2acff4d7e/eb866d5a-1= 319-4e32-b9f3-4de3ad3272fb<o:p></o:p>Thread-1429::DEBUG::2012-06-22 = 09:37:27,507::libvirtvm::1340::vm.Vm::(_run) = vmId=3D`92de99e5-067a-421b-a4b1-2a2b60e8894a`::<?xml = version=3D"1.0" = encoding=3D"utf-8"?><o:p></o:p><domain = type=3D"kvm"><o:p></o:p>=9A=9A=9A=9A=9A=9A=9A = <name>fgjh</name><o:p></o:p>=9A=9A=9A=9A=9A=9A=9A = <uuid>92de99e5-067a-421b-a4b1-2a2b60e8894a</uuid><o:p></o:p><= /span>=9A=9A=9A=9A=9A=9A=9A = <memory>524288</memory><o:p></o:p>=9A=9A=9A=9A=9A=9A=9A = <currentMemory>524288</currentMemory><o:p></o:p><p= class=3DMsoNormal>=9A=9A=9A=9A=9A=9A=9A = <vcpu>1</vcpu><o:p></o:p>=9A=9A=9A=9A=9A=9A=9A = <devices><o:p></o:p>=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A <channel = type=3D"unix"><o:p></o:p>=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A= =9A=9A=9A <target name=3D"com.redhat.rhevm.vdsm" = type=3D"virtio"/><o:p></o:p>=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A= =9A=9A=9A <source mode=3D"bind" = path=3D"/var/lib/libvirt/qemu/channels/fgjh.com.redhat.rhevm.vdsm&qu= ot;/><o:p></o:p>=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A = </channel><o:p></o:p>=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A <input = bus=3D"usb" = type=3D"tablet"/><o:p></o:p>=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A <graphics = autoport=3D"yes" keymap=3D"en-us" = listen=3D"0" passwd=3D"*****" = passwdValidTo=3D"1970-01-01T00:00:01" port=3D"-1" = type=3D"vnc"/><o:p></o:p>=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A <console = type=3D"pty"><o:p></o:p>=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A= =9A=9A=9A <target port=3D"0" = type=3D"virtio"/><o:p></o:p>=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A = </console><o:p></o:p>=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A = <video><o:p></o:p>=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A= =9A=9A=9A <model heads=3D"1" type=3D"qxl" = vram=3D"65536"/><o:p></o:p>=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A = </video><o:p></o:p>=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A <interface = type=3D"bridge"><o:p></o:p>=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A= =9A=9A=9A <mac = address=3D"00:1a:4a:01:14:00"/><o:p></o:p>=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A= =9A=9A=9A <model = type=3D"virtio"/><o:p></o:p>=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A= =9A=9A=9A <source = bridge=3D"ovirtmgmt"/><o:p></o:p>=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A = </interface><o:p></o:p>=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A = <memballoon model=3D"virtio"/><o:p></o:p>=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A <disk = device=3D"cdrom" snapshot=3D"no" = type=3D"file"><o:p></o:p>=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A= =9A=9A=9A <source file=3D""/><o:p></o:p>=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A= =9A=9A=9A <target bus=3D"ide" = dev=3D"hdc"/><o:p></o:p>=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A= =9A=9A=9A <readonly/><o:p></o:p>=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A= =9A=9A=9A <serial></serial><o:p></o:p>=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A = </disk><o:p></o:p>=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A <disk = device=3D"disk" snapshot=3D"no" = type=3D"file"><o:p></o:p>=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A= =9A=9A=9A <source = file=3D"/rhev/data-center/b1c7875a-964d-4633-8ea4-2b191d68c105/68aa0= dc2-9cd1-4549-8008-30b1bae667db/images/61180d3c-63ba-41ca-989a-8bd2acff4d= 7e/eb866d5a-1319-4e32-b9f3-4de3ad3272fb"/><o:p></o:p><= p class=3DMsoNormal>=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A= =9A=9A=9A <target bus=3D"virtio" = dev=3D"vda"/><o:p></o:p>=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A= =9A=9A=9A = <serial>61180d3c-63ba-41ca-989a-8bd2acff4d7e</serial><o:p></o= :p>=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A= =9A=9A=9A <boot order=3D"1"/><o:p></o:p>=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A= =9A=9A=9A <driver cache=3D"none" = error_policy=3D"stop" io=3D"threads" = name=3D"qemu" = type=3D"raw"/><o:p></o:p>=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A = </disk><o:p></o:p>=9A=9A=9A=9A=9A=9A=9A = </devices><o:p></o:p>=9A=9A=9A=9A=9A=9A=9A <os><o:p></o:p>=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A <type = arch=3D"x86_64" = machine=3D"pc">hvm</type><o:p></o:p>=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A <smbios = mode=3D"sysinfo"/><o:p></o:p>=9A=9A=9A=9A=9A=9A=9A = </os><o:p></o:p>=9A=9A=9A=9A=9A=9A=9A <sysinfo = type=3D"smbios"><o:p></o:p>=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A = <system><o:p></o:p>=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A= =9A=9A=9A <entry name=3D"manufacturer">Red = Hat</entry><o:p></o:p>=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A= =9A=9A=9A <entry name=3D"product">RHEV = Hypervisor</entry><o:p></o:p>=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A= =9A=9A=9A <entry = name=3D"version">6.2-1.1</entry><o:p></o:p>= =9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A= =9A=9A=9A <entry = name=3D"serial">068FD200-06AF-7318-06AF-73180A8F5201_00:1c:c= 4:74:94:f0</entry><o:p></o:p>=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A= =9A=9A=9A <entry = name=3D"uuid">92de99e5-067a-421b-a4b1-2a2b60e8894a</entry= ><o:p></o:p>=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A = </system><o:p></o:p>=9A=9A=9A=9A=9A=9A=9A = </sysinfo><o:p></o:p>=9A=9A=9A=9A=9A=9A=9A <clock adjustment=3D"0" = offset=3D"variable"><o:p></o:p>=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A <timer = name=3D"rtc" = tickpolicy=3D"catchup"/><o:p></o:p>=9A=9A=9A=9A=9A=9A=9A = </clock><o:p></o:p>=9A=9A=9A=9A=9A=9A=9A = <features><o:p></o:p>=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A = <acpi/><o:p></o:p>=9A=9A=9A=9A=9A=9A=9A = </features><o:p></o:p>=9A=9A=9A=9A=9A=9A=9A <cpu = match=3D"exact"><o:p></o:p>=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A = <model>Conroe</model><o:p></o:p>=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A=9A <topology = cores=3D"1" sockets=3D"1" = threads=3D"1"/><o:p></o:p>=9A=9A=9A=9A=9A=9A=9A = </cpu><o:p></o:p></domain><o:p></o:p><o:p> </o:p>Thread-1429::DEBUG::2012-06-22 = 09:37:28,084::vm::580::vm.Vm::(_startUnderlyingVm) = vmId=3D`92de99e5-067a-421b-a4b1-2a2b60e8894a`::_ongoingCreations = released<o:p></o:p>Thread-1429::ERROR::2012-06-22 = 09:37:28,084::vm::604::vm.Vm::(_startUnderlyingVm) = vmId=3D`92de99e5-067a-421b-a4b1-2a2b60e8894a`::The vm start process = failed<o:p></o:p>Traceback (most recent call last):<o:p></o:p>=9A File = "/usr/share/vdsm/vm.py", line 570, in = _startUnderlyingVm<o:p></o:p>=9A=9A=9A self._run()<o:p></o:p>=9A File = "/usr/share/vdsm/libvirtvm.py", line 1366, in = _run<o:p></o:p>=9A=9A=9A self._connection.createXML(domxml, = flags),<o:p></o:p>=9A = File = "/usr/lib64/python2.6/site-packages/vdsm/libvirtconnection.py",= line 82, in wrapper<o:p></o:p>=9A=9A=9A ret =3D f(*args, = **kwargs)<o:p></o:p>=9A File = "/usr/lib64/python2.6/site-packages/libvirt.py", line 2087, in = createXML<o:p></o:p>=9A=9A=9A if ret is None:raise = libvirtError('virDomainCreateXML() failed', = conn=3Dself)<o:p></o:p>libvirtError: internal error Process exited while reading = console log output: char device redirected to = /dev/pts/1<o:p></o:p>qemu-kvm: -drive = file=3D/rhev/data-center/b1c7875a-964d-4633-8ea4-2b191d68c105/68aa0dc2-9c= d1-4549-8008-30b1bae667db/images/61180d3c-63ba-41ca-989a-8bd2acff4d7e/eb8= 66d5a-1319-4e32-b9f3-4de3ad3272fb,if=3Dnone,id=3Ddrive-virtio-disk0,forma= t=3Draw,serial=3D61180d3c-63ba-41ca-989a-8bd2acff4d7e,cache=3Dnone,werror= =3Dstop,rerror=3Dstop,aio=3Dthreads: could not open disk image = /rhev/data-center/b1c7875a-964d-4633-8ea4-2b191d68c105/68aa0dc2-9cd1-4549= -8008-30b1bae667db/images/61180d3c-63ba-41ca-989a-8bd2acff4d7e/eb866d5a-1= 319-4e32-b9f3-4de3ad3272fb: Permission denied<o:p></o:p><o:p> </o:p>Thread-1429::DEBUG::2012-06-22 = 09:37:28,087::vm::920::vm.Vm::(setDownStatus) = vmId=3D`92de99e5-067a-421b-a4b1-2a2b60e8894a`::Changed state to Down: = internal error Process exited while reading console log output: char = device redirected to /dev/pts/1<o:p></o:p>qemu-kvm: -drive = file=3D/rhev/data-center/b1c7875a-964d-4633-8ea4-2b191d68c105/68aa0dc2-9c= d1-4549-8008-30b1bae667db/images/61180d3c-63ba-41ca-989a-8bd2acff4d7e/eb8= 66d5a-1319-4e32-b9f3-4de3ad3272fb,if=3Dnone,id=3Ddrive-virtio-disk0,forma= t=3Draw,serial=3D61180d3c-63ba-41ca-989a-8bd2acff4d7e,cache=3Dnone,werror= =3Dstop,rerror=3Dstop,aio=3Dthreads: could not open disk image = /rhev/data-center/b1c7875a-964d-4633-8ea4-2b191d68c105/68aa0dc2-9cd1-4549= -8008-30b1bae667db/images/61180d3c-63ba-41ca-989a-8bd2acff4d7e/eb866d5a-1= 319-4e32-b9f3-4de3ad3272fb: Permission denied<o:p></o:p><o:p> </o:p>Thread-1432::DEBUG::2012-06-22 = 09:37:28,354::BindingXMLRPC::872::vds::(wrapper) client = [10.1.20.2]::call vmGetStats with = ('92de99e5-067a-421b-a4b1-2a2b60e8894a',) {}<o:p></o:p>Thread-1432::DEBUG::2012-06-22 = 09:37:28,354::BindingXMLRPC::879::vds::(wrapper) return vmGetStats with = {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': = 'Down', 'hash': '0', 'exitMessage': 'internal error Process exited while = reading console log output: char device redirected to = /dev/pts/1\nqemu-kvm: -drive = file=3D/rhev/data-center/b1c7875a-964d-4633-8ea4-2b191d68c105/68aa0dc2-9c= d1-4549-8008-30b1bae667db/images/61180d3c-63ba-41ca-989a-8bd2acff4d7e/eb8= 66d5a-1319-4e32-b9f3-4de3ad3272fb,if=3Dnone,id=3Ddrive-virtio-disk0,forma= t=3Draw,serial=3D61180d3c-63ba-41ca-989a-8bd2acff4d7e,cache=3Dnone,werror= =3Dstop,rerror=3Dstop,aio=3Dthreads: could not open disk image = /rhev/data-center/b1c7875a-964d-4633-8ea4-2b191d68c105/68aa0dc2-9cd1-4549= -8008-30b1bae667db/images/61180d3c-63ba-41ca-989a-8bd2acff4d7e/eb866d5a-1= 319-4e32-b9f3-4de3ad3272fb: Permission denied\n', 'vmId': = '92de99e5-067a-421b-a4b1-2a2b60e8894a', 'timeOffset': '0', 'exitCode': = 1}]}<o:p></o:p>Thread-1433::DEBUG::2012-06-22 = 09:37:28,366::BindingXMLRPC::872::vds::(wrapper) client = [10.1.20.2]::call vmDestroy with = ('92de99e5-067a-421b-a4b1-2a2b60e8894a',) {}<o:p></o:p>Thread-1433::INFO::2012-06-22 = 09:37:28,366::API::319::vds::(destroy) vmContainerLock acquired by vm = 92de99e5-067a-421b-a4b1-2a2b60e8894a<o:p></o:p>Thread-1433::DEBUG::2012-06-22 = 09:37:28,366::libvirtvm::2088::vm.Vm::(destroy) = vmId=3D`92de99e5-067a-421b-a4b1-2a2b60e8894a`::destroy = Called<o:p></o:p>Thread-1433::INFO::2012-06-22 = 09:37:28,366::libvirtvm::2042::vm.Vm::(releaseVm) = vmId=3D`92de99e5-067a-421b-a4b1-2a2b60e8894a`::Release VM = resources<o:p></o:p>Thread-1433::WARNING::2012-06-22 = 09:37:28,366::vm::328::vm.Vm::(_set_lastStatus) = vmId=3D`92de99e5-067a-421b-a4b1-2a2b60e8894a`::trying to set state to = Powering down when already Down<o:p></o:p>Thread-1433::DEBUG::2012-06-22 = 09:37:28,367::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo = -n /sbin/service ksmtuned retune' (cwd None)<o:p></o:p>Thread-1433::DEBUG::2012-06-22 = 09:37:28,413::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: = <err> =3D ''; <rc> =3D 0<o:p></o:p>Thread-1433::DEBUG::2012-06-22 = 09:37:28,414::task::588::TaskManager.Task::(_updateState) = Task=3D`f042d1c3-5c18-4cb2-89d9-87d64a560922`::moving from state init = -> state preparing<o:p></o:p>Thread-1433::INFO::2012-06-22 = 09:37:28,415::logUtils::37::dispatcher::(wrapper) Run and protect: = inappropriateDevices(thiefId=3D'92de99e5-067a-421b-a4b1-2a2b60e8894a')<o:= p></o:p>Thread-1433::INFO::2012-06-22 = 09:37:28,418::logUtils::39::dispatcher::(wrapper) Run and protect: = inappropriateDevices, Return response: None<o:p></o:p>Thread-1433::DEBUG::2012-06-22 = 09:37:28,418::task::1172::TaskManager.Task::(prepare) = Task=3D`f042d1c3-5c18-4cb2-89d9-87d64a560922`::finished: = None<o:p></o:p>Thread-1433::DEBUG::2012-06-22 = 09:37:28,418::task::588::TaskManager.Task::(_updateState) = Task=3D`f042d1c3-5c18-4cb2-89d9-87d64a560922`::moving from state = preparing -> state finished<o:p></o:p>Thread-1433::DEBUG::2012-06-22 = 09:37:28,419::resourceManager::809::ResourceManager.Owner::(releaseAll) = Owner.releaseAll requests {} resources {}<o:p></o:p>Thread-1433::DEBUG::2012-06-22 = 09:37:28,419::resourceManager::844::ResourceManager.Owner::(cancelAll) = Owner.cancelAll requests {}<o:p></o:p>Thread-1433::DEBUG::2012-06-22 = 09:37:28,419::task::978::TaskManager.Task::(_decref) = Task=3D`f042d1c3-5c18-4cb2-89d9-87d64a560922`::ref 0 aborting = False<o:p></o:p>Thread-1433::DEBUG::2012-06-22 = 09:37:28,419::libvirtvm::2083::vm.Vm::(deleteVm) = vmId=3D`92de99e5-067a-421b-a4b1-2a2b60e8894a`::Total desktops after = destroy of 92de99e5-067a-421b-a4b1-2a2b60e8894a is = 0<o:p></o:p>Thread-1433::DEBUG::2012-06-22 = 09:37:28,420::BindingXMLRPC::879::vds::(wrapper) return vmDestroy with = {'status': {'message': 'Machine destroyed', 'code': = 0}}<o:p></o:p>Thread-1434::DEBUG::2012-06-22 = 09:37:30,459::task::588::TaskManager.Task::(_updateState) = Task=3D`a479829e-33ba-4c9b-987a-bc61d8bf11d6`::moving from state init = -> state preparing<o:p></o:p>Thread-1434::INFO::2012-06-22 = 09:37:30,459::logUtils::37::dispatcher::(wrapper) Run and protect: = repoStats(options=3DNone)<o:p></o:p>Thread-1434::INFO::2012-06-22 = 09:37:30,459::logUtils::39::dispatcher::(wrapper) Run and protect: = repoStats, Return response: {'68aa0dc2-9cd1-4549-8008-30b1bae667db': = {'delay': '0.0014181137085', 'lastCheck': 1340372243.5057499, 'code': 0, = 'valid': True}}<o:p></o:p>Thread-1434::DEBUG::2012-06-22 = 09:37:30,460::task::1172::TaskManager.Task::(prepare) = Task=3D`a479829e-33ba-4c9b-987a-bc61d8bf11d6`::finished: = {'68aa0dc2-9cd1-4549-8008-30b1bae667db': {'delay': '0.0014181137085', = 'lastCheck': 1340372243.5057499, 'code': 0, 'valid': = True}}<o:p></o:p>Thread-1434::DEBUG::2012-06-22 = 09:37:30,460::task::588::TaskManager.Task::(_updateState) = Task=3D`a479829e-33ba-4c9b-987a-bc61d8bf11d6`::moving from state = preparing -> state finished<o:p></o:p>Thread-1434::DEBUG::2012-06-22 = 09:37:30,460::resourceManager::809::ResourceManager.Owner::(releaseAll) = Owner.releaseAll requests {} resources {}<o:p></o:p>Thread-1434::DEBUG::2012-06-22 = 09:37:30,460::resourceManager::844::ResourceManager.Owner::(cancelAll) = Owner.cancelAll requests {}<o:p></o:p>Thread-1434::DEBUG::2012-06-22 = 09:37:30,460::task::978::TaskManager.Task::(_decref) = Task=3D`a479829e-33ba-4c9b-987a-bc61d8bf11d6`::ref 0 aborting = False<o:p></o:p>^C<o:p></o:p><o:p> </o:p>Error:<o:p></o:p>libvirtError: internal error Process exited while reading = console log output: char device redirected to = /dev/pts/1<o:p></o:p>qemu-kvm: -drive = file=3D/rhev/data-center/b1c7875a-964d-4633-8ea4-2b191d68c105/68aa0dc2-9c= d1-4549-8008-30b1bae667db/images/61180d3c-63ba-41ca-989a-8bd2acff4d7e/eb8= 66d5a-1319-4e32-b9f3-4de3ad3272fb,if=3Dnone,id=3Ddrive-virtio-disk0,forma= t=3Draw,serial=3D61180d3c-63ba-41ca-989a-8bd2acff4d7e,cache=3Dnone,werror= =3Dstop,rerror=3Dstop,aio=3Dthreads: could not open disk image = /rhev/data-center/b1c7875a-964d-4633-8ea4-2b191d68c105/68aa0dc2-9cd1-4549= -8008-30b1bae667db/images/61180d3c-63ba-41ca-989a-8bd2acff4d7e/eb866d5a-1= 319-4e32-b9f3-4de3ad3272fb: Permission denied<o:p></o:p><o:p> </o:p>[root@noc-3-synt mnt]# ls -lh = /rhev/data-center/b1c7875a-964d-4633-8ea4-2b191d68c105/68aa0dc2-9cd1-4549= -8008-30b1bae667db/images/61180d3c-63ba-41ca-989a-8bd2acff4d7e/eb866d5a-1= 319-4e32-b9f3-4de3ad3272fb<o:p></o:p>-rw-rw----. 1 vdsm kvm 10G Jun 22 = 09:28 = /rhev/data-center/b1c7875a-964d-4633-8ea4-2b191d68c105/68aa0dc2-9cd1-4549= -8008-30b1bae667db/images/61180d3c-63ba-41ca-989a-8bd2acff4d7e/eb866d5a-1= 319-4e32-b9f3-4de3ad3272fb<o:p></o:p><o:p> </o:p>[root@noc-3-synt mnt]# ps -aux | = grep /usr/share/vdsm/vdsm<o:p></o:p>Warning: bad syntax, perhaps a = bogus '-'? See /usr/share/doc/procps-3.2.8/FAQ<o:p></o:p>root=9A=9A=9A=9A=9A 2761=9A 0.0=9A = 0.0 103280=9A=9A 804 pts/0=9A=9A=9A S+=9A=9A 09:51=9A=9A 0:00 grep = /usr/share/vdsm/vdsm<o:p></o:p>vdsm=9A=9A=9A=9A=9A 4480=9A 0.0=9A 0.0=9A=9A 9272=9A=9A 616 = ?=9A=9A=9A=9A=9A=9A=9A S<=9A=9A 09:07=9A=9A 0:00 /bin/bash -e = /usr/share/vdsm/respawn --minlifetime 10 --daemon --masterpid = /var/run/vdsm/respawn.pid /usr/share/vdsm/vdsm<o:p></o:p>vdsm=9A=9A=9A=9A=9A 4483=9A 0.6=9A = 0.2 1411684 34800 ?=9A=9A=9A=9A=9A=9A S<l=9A 09:07=9A=9A 0:17 = /usr/bin/python /usr/share/vdsm/vdsm<o:p></o:p>vdsm=9A=9A=9A=9A=9A 5265=9A 0.0=9A = 0.1 1387096 26880 ?=9A=9A=9A=9A=9A=9A S<=9A=9A 09:17=9A=9A 0:00 = /usr/bin/python /usr/share/vdsm/vdsm<o:p></o:p>vdsm=9A=9A=9A=9A=9A 5266=9A 0.0=9A = 0.1 1387096 26660 ?=9A=9A=9A=9A=9A=9A S<=9A=9A 09:17=9A=9A 0:00 = /usr/bin/python /usr/share/vdsm/vdsm<o:p></o:p>vdsm=9A=9A=9A=9A=9A 5267=9A 0.0=9A = 0.1 1387096 26660 ?=9A=9A=9A=9A=9A=9A S<=9A=9A 09:17=9A=9A 0:00 = /usr/bin/python /usr/share/vdsm/vdsm<o:p></o:p>vdsm=9A=9A =9A=9A=9A5269=9A 0.0=9A = 0.1 1387096 26584 ?=9A=9A=9A=9A=9A=9A S<=9A=9A 09:17=9A=9A 0:00 = /usr/bin/python /usr/share/vdsm/vdsm<o:p></o:p>vdsm=9A=9A=9A=9A=9A 5271=9A 0.0=9A = 0.1 1387096 26584 ?=9A=9A=9A=9A=9A=9A S<=9A=9A 09:17=9A=9A 0:00 = /usr/bin/python /usr/share/vdsm/vdsm<o:p></o:p>….<o:p></o:p><o:p> </o:p><o:p> </o:p><o:p> </o:p></div></body></html> ------=_NextPart_000_00B5_01CD50A1.2C0D2C70--

2 3