- Users - oVirt List Archives

[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

[Users] host install failed (kernel version 3.4.3)
by зоррыч 25 Jun '12

25 Jun '12

This is a multipart message in MIME format. ------=_NextPart_000_0092_01CD50D6.DF9FD5F0 Content-Type: text/plain; charset="koi8-r" Content-Transfer-Encoding: 7bit Hi. I am trying to install the host kernel with version 3.4.3. an error: Unsupported kernel version: 0 Logs: [root@noc-3-synt tmp]# cat vds_bootstrap.372080.log Fri, 22 Jun 2012 16:08:20 DEBUG **** Start VDS Validation **** Fri, 22 Jun 2012 16:08:20 DEBUG Entered VdsValidation(subject = '10.1.20.7', random_num = '7d832636-a512-40ae-8e27-ecd24728b39a', rev_num = 'None', installVirtualizationService = 'False', installGlusterService = 'True') Fri, 22 Jun 2012 16:08:20 DEBUG Setting up Package Sacks Fri, 22 Jun 2012 16:08:20 DEBUG yumSearch: found vdsm entries: [<YumAvailablePackageSqlite : vdsm-4.10.0-0.58.gita6f4929.el6.x86_64 (0x1b42a10)>] Fri, 22 Jun 2012 16:08:20 DEBUG Host properly registered with RHN/Satellite. Fri, 22 Jun 2012 16:08:20 DEBUG <BSTRAP component='RHN_REGISTRATION' status='OK' message='Host properly registered with RHN/Satellite.'/> Fri, 22 Jun 2012 16:08:21 DEBUG yumSearchVersion: pkg vdsm-4.10.0-0.58.gita6f4929.el6.x86_64 starts with: vdsm-4.10 Fri, 22 Jun 2012 16:08:21 DEBUG Available VDSM matches requirements Fri, 22 Jun 2012 16:08:21 DEBUG <BSTRAP component='VDSM_MAJOR_VER' status='OK' message='Available VDSM matches requirements'/> Fri, 22 Jun 2012 16:08:21 DEBUG ['/bin/uname', '-r'] Fri, 22 Jun 2012 16:08:21 DEBUG 3.4.3 Fri, 22 Jun 2012 16:08:21 DEBUG Fri, 22 Jun 2012 16:08:21 DEBUG <BSTRAP component='OS' status='OK' type='RHEL6' message='Supported platform version'/> Fri, 22 Jun 2012 16:08:21 DEBUG <BSTRAP component='KERNEL' status='FAIL' version='0' message='Unsupported kernel version: 0. Minimal supported version: 150'/> Fri, 22 Jun 2012 16:08:21 ERROR osExplorer test failed Fri, 22 Jun 2012 16:08:21 DEBUG <BSTRAP component='RHEV_INSTALL' status='FAIL'/> Fri, 22 Jun 2012 16:08:21 DEBUG **** End VDS Validation **** [root@noc-3-synt tmp]# uname -r 3.4.3 ------=_NextPart_000_0092_01CD50D6.DF9FD5F0 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=3DContent-Type content=3D"text/html; charset=3Dkoi8-r"><meta = name=3DGenerator content=3D"Microsoft Word 14 (filtered = medium)"><style></style></head><body lang=3DRU link=3Dblue = vlink=3Dpurple><div class=3DWordSection1>Hi.<o:p></o:p>I am trying to install the host kernel with version = 3.4.3.<o:p></o:p>an = error:<o:p></o:p>Unsupported kernel version: 0<o:p></o:p>Logs:<o:p></o:p><o:p> </o:p>[root@noc-3-synt tmp]# cat = vds_bootstrap.372080.log<o:p></o:p>Fri, 22 Jun 2012 16:08:20 DEBUG=9A=9A=9A **** Start VDS = Validation ****<o:p></o:p>Fri, 22 Jun 2012 16:08:20 DEBUG=9A=9A=9A Entered = VdsValidation(subject =3D '10.1.20.7', random_num =3D = '7d832636-a512-40ae-8e27-ecd24728b39a', rev_num =3D 'None', = installVirtualizationService =3D 'False', installGlusterService =3D = 'True')<o:p></o:p>Fri, 22 Jun 2012 16:08:20 DEBUG=9A =9A=9ASetting up Package = Sacks<o:p></o:p>Fri, = 22 Jun 2012 16:08:20 DEBUG=9A=9A=9A yumSearch: found vdsm entries: = [<YumAvailablePackageSqlite : vdsm-4.10.0-0.58.gita6f4929.el6.x86_64 = (0x1b42a10)>]<o:p></o:p>Fri, 22 Jun 2012 16:08:20 DEBUG=9A=9A=9A Host properly = registered with RHN/Satellite.<o:p></o:p>Fri, 22 Jun 2012 16:08:20 = DEBUG=9A=9A=9A <BSTRAP component=3D'RHN_REGISTRATION' status=3D'OK' = message=3D'Host properly registered with = RHN/Satellite.'/><o:p></o:p>Fri, 22 Jun 2012 16:08:21 DEBUG=9A=9A=9A yumSearchVersion: = pkg vdsm-4.10.0-0.58.gita6f4929.el6.x86_64 starts with: = vdsm-4.10<o:p></o:p>Fri, 22 Jun 2012 16:08:21 DEBUG=9A=9A=9A Available VDSM = matches requirements<o:p></o:p>Fri, 22 Jun 2012 16:08:21 DEBUG=9A=9A=9A <BSTRAP = component=3D'VDSM_MAJOR_VER' status=3D'OK' message=3D'Available VDSM = matches requirements'/><o:p></o:p>Fri, 22 Jun 2012 16:08:21 = DEBUG=9A=9A=9A ['/bin/uname', '-r']<o:p></o:p>Fri, 22 Jun 2012 16:08:21 = DEBUG=9A=9A=9A 3.4.3<o:p></o:p><o:p> </o:p>Fri, 22 Jun 2012 16:08:21 DEBUG<o:p></o:p>Fri, 22 Jun 2012 16:08:21 = DEBUG=9A=9A=9A <BSTRAP component=3D'OS' status=3D'OK' type=3D'RHEL6' = message=3D'Supported platform version'/><o:p></o:p>Fri, 22 Jun 2012 16:08:21 = DEBUG=9A=9A=9A <BSTRAP component=3D'KERNEL' status=3D'FAIL' = version=3D'0' message=3D'Unsupported kernel version: 0. Minimal = supported version: 150'/><o:p></o:p>Fri, 22 Jun 2012 16:08:21 = ERROR=9A=9A=9A osExplorer test failed<o:p></o:p>Fri, 22 Jun 2012 16:08:21 = DEBUG=9A=9A=9A <BSTRAP component=3D'RHEV_INSTALL' = status=3D'FAIL'/><o:p></o:p>Fri, 22 Jun 2012 16:08:21 DEBUG=9A=9A=9A **** End VDS = Validation ****<o:p></o:p><o:p> </o:p>[root@noc-3-synt tmp]# uname -r<o:p></o:p>3.4.3<o:p></o:p></div></body></html> ------=_NextPart_000_0092_01CD50D6.DF9FD5F0--

3 3

[Users] Quantum support
by Rahul Upadhyaya 25 Jun '12

25 Jun '12

Hi Folks, According to your road-map, when shall quantum support be available for oVirt ? -- Regards, Rahul =======================================================

2 1

[Users] Getting a stream of errors inside engine.log
by Robert Middleswarth 25 Jun '12

25 Jun '12

Getting a log full of error messages like these. 2012-06-21 21:03:30,075 ERROR [org.ovirt.engine.core.engineencryptutils.EncryptionUtils] (QuartzScheduler_Worker-90) Failed to decryptData must start with zero 2012-06-21 21:03:46,235 ERROR [org.ovirt.engine.core.engineencryptutils.EncryptionUtils] (QuartzScheduler_Worker-18) Failed to decryptData must not be longer than 128 bytes What is causing this and what can I do to fix it? Thanks Robert

4 10

[Users] oVirt 3.1 and Glusterfs using NFS shares.
by Robert Middleswarth 24 Jun '12

24 Jun '12

It took me a while with lots of trail and error but I am pretty close to getting everything working but my latest error seems to be permission related. Very much like the error one gets with regular nfs and the share not owned by the correct uid/gid. But there doesn't seem to be a way to fix it. According to this doc http://www.gluster.org/community/documentation/index.php/Translators/featur… on the Gluster site you can set those but I don't see a way to set that inside the interface and the files I would need to change get over written but vdsm. Am I missing something really obvious? Has anyone actually been able to get ovirt and glusterfs running together. I feel like I am so close just missing one little piece of the puzzle. Thanks Robert

2 4

[Users] I am using the CentOS build from the 12th. I the engine is dieing with the following error.
by Robert Middleswarth 24 Jun '12

24 Jun '12

2012-06-17 05:21:24,682 ERROR [org.ovirt.engine.core.engineencryptutils.EncryptionUtils] (ajp--0.0.0.0-8009-9) Failed to decryptjava.io.FileNotFoundException: /etc/pki/ovirt-engine/.keystore (Too many open files) 2012-06-17 05:21:26,121 ERROR [org.ovirt.engine.core.engineencryptutils.EncryptionUtils] (QuartzScheduler_Worker-88) Failed to decryptjava.io.FileNotFoundException: /etc/pki/ovirt-engine/.keystore (Too many open files) 2012-06-17 05:21:26,130 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand] (QuartzScheduler_Worker-88) XML RPC error in command GetCapabilitiesVDS ( Vds: ann100ovirt01 ), the error was: java.util.concurrent.ExecutionException: java.lang.reflect.InvocationTargetException, SocketException: Too many open files 2012-06-17 15:49:08,577 ERROR [org.ovirt.engine.core.engineencryptutils.EncryptionUtils] (QuartzScheduler_Worker-28) Failed to decryptjava.io.FileNotFoundException: /etc/pki/ovirt-engine/.keystore (Too many open files) 2012-06-17 20:21:13,943 ERROR [org.ovirt.engine.core.engineencryptutils.EncryptionUtils] (QuartzScheduler_Worker-64) Failed to decryptjava.io.FileNotFoundException: /etc/pki/ovirt-engine/.keystore (Too many open files) 2012-06-17 20:21:15,949 ERROR [org.ovirt.engine.core.engineencryptutils.EncryptionUtils] (QuartzScheduler_Worker-65) Failed to decryptjava.io.FileNotFoundException: /etc/pki/ovirt-engine/.keystore (Too many open files) 2012-06-17 21:00:15,133 ERROR [org.ovirt.engine.core.engineencryptutils.EncryptionUtils] (QuartzScheduler_Worker-98) Failed to decryptjava.io.FileNotFoundException: /etc/pki/ovirt-engine/.keystore (Too many open files) 2012-06-17 21:07:00,037 WARN [org.ovirt.engine.core.ServletUtils] (ajp--0.0.0.0-8009-5) File "/usr/share/vdsm-bootstrap/deployUtil.py is 47867 bytes long. Please reconsider using this servlet for files larger than 8192 bytes. 2012-06-17 21:07:00,115 WARN [org.ovirt.engine.core.ServletUtils] (ajp--0.0.0.0-8009-6) File "/usr/share/vdsm-bootstrap/vds_bootstrap.py is 33884 bytes long. Please reconsider using this servlet for files larger than 8192 bytes. 2012-06-17 21:32:10,686 WARN [org.ovirt.engine.core.ServletUtils] (ajp--0.0.0.0-8009-6) File "/usr/share/vdsm-bootstrap/deployUtil.py is 47867 bytes long. Please reconsider using this servlet for files larger than 8192 bytes. 2012-06-17 21:32:10,752 WARN [org.ovirt.engine.core.ServletUtils] (ajp--0.0.0.0-8009-1) File "/usr/share/vdsm-bootstrap/vds_bootstrap.py is 33884 bytes long. Please reconsider using this servlet for files larger than 8192 bytes. 2012-06-17 21:44:34,028 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand] (QuartzScheduler_Worker-23) XML RPC error in command ListVDS ( Vds: ann100ovirt01 ), the error was: java.util.concurrent.ExecutionException: java.lang.reflect.InvocationTargetException, SocketException: Too many open files 2012-06-17 21:44:36,034 ERROR [org.ovirt.engine.core.engineencryptutils.EncryptionUtils] (QuartzScheduler_Worker-26) Failed to decryptjava.io.FileNotFoundException: /etc/pki/ovirt-engine/.keystore (Too many open files) 2012-06-17 21:44:36,045 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand] (QuartzScheduler_Worker-26) XML RPC error in command GetCapabilitiesVDS ( Vds: ann100ovirt01 ), the error was: java.util.concurrent.ExecutionException: java.lang.reflect.InvocationTargetException, SocketException: Too many open files I restarted ovirt-engine and ran lsof -p 3557 I see hundreds of the same open file. java 3557 ovirt 839r REG 253,0 3230 7865608 /etc/pki/ovirt-engine/.keystore java 3557 ovirt 840r REG 253,0 3230 7865608 /etc/pki/ovirt-engine/.keystore java 3557 ovirt 841r REG 253,0 3230 7865608 /etc/pki/ovirt-engine/.keystore java 3557 ovirt 842r REG 253,0 3230 7865608 /etc/pki/ovirt-engine/.keystore java 3557 ovirt 843r REG 253,0 3230 7865608 /etc/pki/ovirt-engine/.keystore java 3557 ovirt 844r REG 253,0 3230 7865608 /etc/pki/ovirt-engine/.keystore java 3557 ovirt 845r REG 253,0 3230 7865608 /etc/pki/ovirt-engine/.keystore java 3557 ovirt 846r REG 253,0 3230 7865608 /etc/pki/ovirt-engine/.keystore java 3557 ovirt 847r REG 253,0 3230 7865608 /etc/pki/ovirt-engine/.keystore java 3557 ovirt 848r REG 253,0 3230 7865608 /etc/pki/ovirt-engine/.keystore java 3557 ovirt 849r REG 253,0 3230 7865608 /etc/pki/ovirt-engine/.keystore java 3557 ovirt 850r REG 253,0 3230 7865608 /etc/pki/ovirt-engine/.keystore java 3557 ovirt 851r REG 253,0 3230 7865608 /etc/pki/ovirt-engine/.keystore java 3557 ovirt 852r REG 253,0 3230 7865608 /etc/pki/ovirt-engine/.keystore java 3557 ovirt 853r REG 253,0 3230 7865608 /etc/pki/ovirt-engine/.keystore java 3557 ovirt 854r REG 253,0 3230 7865608 /etc/pki/ovirt-engine/.keystore Is anyone else seeing this? Thanks Robert

4 10

[Users] VDSM ERROR
by Nathan Stratton 24 Jun '12

24 Jun '12

Fedora 17 RPMs, hosts complets install and reboots, but never connects back to engine. I just see thousands of the following in the logs: ---- MainThread::INFO::2012-06-21 13:07:26,304::vdsm::71::vds::(run) I am the actual vdsm 4.9-0 MainThread::ERROR::2012-06-21 13:07:26,656::vdsm::74::vds::(run) Traceback (most recent call last): File "/usr/share/vdsm/vdsm", line 72, in run serve_clients(log) File "/usr/share/vdsm/vdsm", line 40, in serve_clients cif = clientIF.clientIF(log) File "/usr/share/vdsm/clientIF.py", line 115, in __init__ self._createLibvirtNetworks() File "/usr/share/vdsm/clientIF.py", line 152, in _createLibvirtNetworks nf = netinfo.NetInfo() File "/usr/share/vdsm/netinfo.py", line 268, in __init__ _netinfo = get() File "/usr/share/vdsm/netinfo.py", line 215, in get for bridge in bridges() ]) KeyError: 'ovirtmgmt' MainThread::INFO::2012-06-21 13:07:26,657::vdsm::76::vds::(run) VDSM main thread ended. Waiting for 1 other threads... MainThread::INFO::2012-06-21 13:07:26,657::vdsm::79::vds::(run) <_MainThread(MainThread, started 140487047427904)> MainThread::INFO::2012-06-21 13:07:26,657::vdsm::79::vds::(run) <Thread(libvirtEventLoop, started daemon 140486974248704)> ---- ovirtmgmt is up and running: -bash-4.2# brctl show bridge name bridge id STP enabled interfaces ovirtmgmt 8000.a0369f0a15f8 no bond0 ><> Nathan Stratton nathan at robotics.net http://www.robotics.net

3 5