Description of problem: I installed ovirt node using the new oVirt Node 2.5.2 ISO. NFS works fine now. However: I cannot start any virtual machine, neither new created of imported old ones. I'm using local storage. /var/log/vdsm/libvirt.log ends with: 2012-10-07 14:54:03.693+0000: 22744: error : virNetClientProgramDispatchError:174 : internal error unsupported configuration: Read/write, exclusive access, disks were present, but no leases specified How reproducible: Import virtual server from export domain. Server doesn't start. Create new virtual server. Server doesn't start. Check /var/log/vdsm/libvirt.log on ovirt Node. It will show "Internal error unsupported configuration: Read/write, exclusive access, disks were present, but no leases specified" Actual results: Server fails to start. Expected results: Server should start Additional info:
What's the libvirt version? What's the content of /etc/libvirt/qemu-sanlock.conf and /etc/libvirt/qemu-sanlock.conf? (only the parts within the vdsm configuration section marked by the comments).
Libvirt as provided in oVirt Node: [root@localhost admin]# rpm -qi libvirt Name : libvirt Version : 0.9.11.5 Release : 3.fc17 Architecture: x86_64 Install Date: Fri Oct 5 13:36:57 2012 Group : Development/Libraries Size : 0 License : LGPLv2+ Signature : RSA/SHA256, Wed Aug 22 15:20:01 2012, Key ID 50e94c991aca3465 Source RPM : libvirt-0.9.11.5-3.fc17.src.rpm Build Date : Wed Aug 22 14:27:01 2012 Build Host : buildvm-07.phx2.fedoraproject.org Relocations : (not relocatable) Packager : Fedora Project Vendor : Fedora Project URL : http://libvirt.org/ Summary : Library providing a simple virtualization API /etc/libvirt/qemu-sanlock.conf: ~ ## beginning of configuration section by vdsm-4.9.6 auto_disk_leases=0 require_lease_for_disks=0 ## end of configuration section by vdsm-4.9.6
Sorry in comment 1 one of the config files that I needed was /etc/libvirt/qemu.conf, but never mind I'm pretty sure it contains lock_manager="sanlock". Could you try to restart the libvirt service? We define require_lease_for_disks=0 and looking at the libvirt code everything looks correct. The only thing that I can think of is that the config file was generated after the libvirt service was started. BTW, is there anything in the libvirt logs regarding the qemu-sanlock.conf config file? (eg: unable to find or open/parse it).
[root@localhost admin]# grep lock_manager /etc/libvirt/qemu.conf #lock_manager = "sanlock" lock_manager="sanlock" I'll check later.
[root@localhost admin]# grep sanlock /etc/libvirt/qemu.conf #lock_manager = "sanlock" lock_manager="sanlock" [root@localhost admin]# grep lease /etc/libvirt/qemu-sanlock.conf ~ auto_disk_leases=0 require_lease_for_disks=0 [root@localhost admin]# systemctl restart libvirtd.service; systemctl status libvirtd.service libvirtd.service - Virtualization daemon Loaded: loaded (/usr/lib/systemd/system/libvirtd.service; enabled) Active: active (running) since Mon, 08 Oct 2012 17:01:29 +0000; 13ms ago Main PID: 10857 (libvirtd) CGroup: name=systemd:/system/libvirtd.service └ 10857 /usr/sbin/libvirtd --listen still results in "Failed to run VM PXE (User: admin@internal)." [root@localhost log]# pwd /var/log [root@localhost log]# grep -iR qemu-sanlock.conf * <no result> Now, that's interesting, in libvirt.log: 2012-10-08 17:07:15.862+0000: 16123: error : virNetClientProgramDispatchError:174 : internal error Failed to open socket to sanlock daemon: Permission denied setenforce 0 Start virtual machine Party! Machines start OK. This seems to be a SELinux issue as well.
OK, again: reboot the machine. Local storage fails to become active. After "setenforce 0" it does. Virtual machines starts fine now. [root@localhost vdsm]# ausearch -m avc -ts today ---- time->Mon Oct 8 16:42:47 2012 type=PATH msg=audit(1349714567.414:27): item=0 name="/usr/sbin/libvirtd" inode=12161 dev=fd:04 mode=0100755 ouid=0 ogid=0 rdev=00:00 obj=system_u:object_r:virtd_exec_t:s0 type=CWD msg=audit(1349714567.414:27): cwd="/var/lib/collectd" type=SYSCALL msg=audit(1349714567.414:27): arch=c000003e syscall=4 success=no exit=-13 a0=7f114ba71cac a1=7f1142600720 a2=7f1142600720 a3=7f11426004b0 items=1 ppid=1 pid=1072 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="collectd" exe="/usr/sbin/collectd" subj=system_u:system_r:collectd_t:s0 key=(null) type=AVC msg=audit(1349714567.414:27): avc: denied { getattr } for pid=1072 comm="collectd" path="/usr/sbin/libvirtd" dev="dm-4" ino=12161 scontext=system_u:system_r:collectd_t:s0 tcontext=system_u:object_r:virtd_exec_t:s0 tclass=file ---- time->Mon Oct 8 16:42:47 2012 type=PATH msg=audit(1349714567.587:29): item=0 name="/var/lib/rpm/Packages" inode=13752 dev=fd:04 mode=0100644 ouid=0 ogid=0 rdev=00:00 obj=unconfined_u:object_r:var_t:s0 type=CWD msg=audit(1349714567.587:29): cwd="/" type=SYSCALL msg=audit(1349714567.587:29): arch=c000003e syscall=4 success=no exit=-13 a0=7ff8c8bda000 a1=7fffe18687a0 a2=7fffe18687a0 a3=5 items=1 ppid=1 pid=982 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="snmpd" exe="/usr/sbin/snmpd" subj=system_u:system_r:snmpd_t:s0 key=(null) type=AVC msg=audit(1349714567.587:29): avc: denied { getattr } for pid=982 comm="snmpd" path="/var/lib/rpm/Packages" dev="dm-4" ino=13752 scontext=system_u:system_r:snmpd_t:s0 tcontext=unconfined_u:object_r:var_t:s0 tclass=file ---- time->Mon Oct 8 16:42:51 2012 type=PATH msg=audit(1349714571.862:41): item=0 name="/proc/self/fd/0" inode=23758 dev=00:21 mode=0100600 ouid=0 ogid=0 rdev=00:00 obj=system_u:object_r:initrc_tmp_t:s0 type=CWD msg=audit(1349714571.862:41): cwd="/" type=SYSCALL msg=audit(1349714571.862:41): arch=c000003e syscall=2 success=no exit=-13 a0=40abf4 a1=2 a2=7f7a606d825c a3=7fff46a18480 items=1 ppid=1707 pid=1724 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="loadkeys" exe="/usr/bin/loadkeys" subj=system_u:system_r:loadkeys_t:s0 key=(null) type=AVC msg=audit(1349714571.862:41): avc: denied { write } for pid=1724 comm="loadkeys" dev="tmpfs" ino=23758 scontext=system_u:system_r:loadkeys_t:s0 tcontext=system_u:object_r:initrc_tmp_t:s0 tclass=file ---- time->Mon Oct 8 16:42:51 2012 type=PATH msg=audit(1349714571.862:42): item=0 name="/proc/self/fd/0" inode=23758 dev=00:21 mode=0100600 ouid=0 ogid=0 rdev=00:00 obj=system_u:object_r:initrc_tmp_t:s0 type=CWD msg=audit(1349714571.862:42): cwd="/" type=SYSCALL msg=audit(1349714571.862:42): arch=c000003e syscall=2 success=no exit=-13 a0=40abf4 a1=1 a2=d a3=7fff46a18480 items=1 ppid=1707 pid=1724 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="loadkeys" exe="/usr/bin/loadkeys" subj=system_u:system_r:loadkeys_t:s0 key=(null) type=AVC msg=audit(1349714571.862:42): avc: denied { write } for pid=1724 comm="loadkeys" dev="tmpfs" ino=23758 scontext=system_u:system_r:loadkeys_t:s0 tcontext=system_u:object_r:initrc_tmp_t:s0 tclass=file ---- time->Mon Oct 8 16:42:51 2012 type=PATH msg=audit(1349714571.862:43): item=0 name="/proc/self/fd/0" inode=23758 dev=00:21 mode=0100600 ouid=0 ogid=0 rdev=00:00 obj=system_u:object_r:initrc_tmp_t:s0 type=CWD msg=audit(1349714571.862:43): cwd="/" type=SYSCALL msg=audit(1349714571.862:43): arch=c000003e syscall=2 success=no exit=-13 a0=40abf4 a1=0 a2=d a3=7fff46a18480 items=1 ppid=1707 pid=1724 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="loadkeys" exe="/usr/bin/loadkeys" subj=system_u:system_r:loadkeys_t:s0 key=(null) type=AVC msg=audit(1349714571.862:43): avc: denied { open } for pid=1724 comm="loadkeys" path=2F746D702F73682D7468642D31333439373339353831202864656C6574656429 dev="tmpfs" ino=23758 scontext=system_u:system_r:loadkeys_t:s0 tcontext=system_u:object_r:initrc_tmp_t:s0 tclass=file ---- time->Mon Oct 8 16:42:51 2012 type=SYSCALL msg=audit(1349714571.865:44): arch=c000003e syscall=16 success=no exit=-13 a0=0 a1=5401 a2=7fff27312e20 a3=7fff27312db0 items=0 ppid=1724 pid=1725 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="sh" exe="/usr/bin/bash" subj=system_u:system_r:loadkeys_t:s0 key=(null) type=AVC msg=audit(1349714571.865:44): avc: denied { ioctl } for pid=1725 comm="sh" path=2F746D702F73682D7468642D31333439373339353831202864656C6574656429 dev="tmpfs" ino=23758 scontext=system_u:system_r:loadkeys_t:s0 tcontext=system_u:object_r:initrc_tmp_t:s0 tclass=file ---- time->Mon Oct 8 16:42:51 2012 type=SYSCALL msg=audit(1349714571.884:45): arch=c000003e syscall=16 success=no exit=-13 a0=0 a1=5401 a2=7fff43faf260 a3=7fff43faf1f0 items=0 ppid=1724 pid=1726 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="sh" exe="/usr/bin/bash" subj=system_u:system_r:loadkeys_t:s0 key=(null) type=AVC msg=audit(1349714571.884:45): avc: denied { ioctl } for pid=1726 comm="sh" path=2F746D702F73682D7468642D31333439373339353831202864656C6574656429 dev="tmpfs" ino=23758 scontext=system_u:system_r:loadkeys_t:s0 tcontext=system_u:object_r:initrc_tmp_t:s0 tclass=file ---- time->Mon Oct 8 16:42:51 2012 type=PATH msg=audit(1349714571.889:46): item=0 name="/proc/self/fd/0" inode=23758 dev=00:21 mode=0100600 ouid=0 ogid=0 rdev=00:00 obj=system_u:object_r:initrc_tmp_t:s0 type=CWD msg=audit(1349714571.889:46): cwd="/" type=SYSCALL msg=audit(1349714571.889:46): arch=c000003e syscall=2 success=no exit=-13 a0=40abf4 a1=2 a2=23c0580 a3=c7 items=1 ppid=1707 pid=1724 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="loadkeys" exe="/usr/bin/loadkeys" subj=system_u:system_r:loadkeys_t:s0 key=(null) type=AVC msg=audit(1349714571.889:46): avc: denied { write } for pid=1724 comm="loadkeys" dev="tmpfs" ino=23758 scontext=system_u:system_r:loadkeys_t:s0 tcontext=system_u:object_r:initrc_tmp_t:s0 tclass=file ---- time->Mon Oct 8 16:42:51 2012 type=PATH msg=audit(1349714571.890:47): item=0 name="/proc/self/fd/0" inode=23758 dev=00:21 mode=0100600 ouid=0 ogid=0 rdev=00:00 obj=system_u:object_r:initrc_tmp_t:s0 type=CWD msg=audit(1349714571.890:47): cwd="/" type=SYSCALL msg=audit(1349714571.890:47): arch=c000003e syscall=2 success=no exit=-13 a0=40abf4 a1=1 a2=d a3=c7 items=1 ppid=1707 pid=1724 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="loadkeys" exe="/usr/bin/loadkeys" subj=system_u:system_r:loadkeys_t:s0 key=(null) type=AVC msg=audit(1349714571.890:47): avc: denied { write } for pid=1724 comm="loadkeys" dev="tmpfs" ino=23758 scontext=system_u:system_r:loadkeys_t:s0 tcontext=system_u:object_r:initrc_tmp_t:s0 tclass=file ---- time->Mon Oct 8 16:42:51 2012 type=PATH msg=audit(1349714571.890:48): item=0 name="/proc/self/fd/0" inode=23758 dev=00:21 mode=0100600 ouid=0 ogid=0 rdev=00:00 obj=system_u:object_r:initrc_tmp_t:s0 type=CWD msg=audit(1349714571.890:48): cwd="/" type=SYSCALL msg=audit(1349714571.890:48): arch=c000003e syscall=2 success=no exit=-13 a0=40abf4 a1=0 a2=d a3=c7 items=1 ppid=1707 pid=1724 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="loadkeys" exe="/usr/bin/loadkeys" subj=system_u:system_r:loadkeys_t:s0 key=(null) type=AVC msg=audit(1349714571.890:48): avc: denied { open } for pid=1724 comm="loadkeys" path=2F746D702F73682D7468642D31333439373339353831202864656C6574656429 dev="tmpfs" ino=23758 scontext=system_u:system_r:loadkeys_t:s0 tcontext=system_u:object_r:initrc_tmp_t:s0 tclass=file ---- time->Mon Oct 8 16:43:07 2012 type=PATH msg=audit(1349714587.412:56): item=0 name="/usr/sbin/libvirtd" inode=12161 dev=fd:04 mode=0100755 ouid=0 ogid=0 rdev=00:00 obj=system_u:object_r:virtd_exec_t:s0 type=CWD msg=audit(1349714587.412:56): cwd="/var/lib/collectd" type=SYSCALL msg=audit(1349714587.412:56): arch=c000003e syscall=4 success=no exit=-13 a0=7f114ba71cac a1=7f1142600720 a2=7f1142600720 a3=722f7261762f2065 items=1 ppid=1 pid=1072 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="collectd" exe="/usr/sbin/collectd" subj=system_u:system_r:collectd_t:s0 key=(null) type=AVC msg=audit(1349714587.412:56): avc: denied { getattr } for pid=1072 comm="collectd" path="/usr/sbin/libvirtd" dev="dm-4" ino=12161 scontext=system_u:system_r:collectd_t:s0 tcontext=system_u:object_r:virtd_exec_t:s0 tclass=file ---- time->Mon Oct 8 16:43:47 2012 type=PATH msg=audit(1349714627.412:142): item=0 name="/usr/sbin/libvirtd" inode=12161 dev=fd:04 mode=0100755 ouid=0 ogid=0 rdev=00:00 obj=system_u:object_r:virtd_exec_t:s0 type=CWD msg=audit(1349714627.412:142): cwd="/var/lib/collectd" type=SYSCALL msg=audit(1349714627.412:142): arch=c000003e syscall=4 success=no exit=-13 a0=7f114ba71cac a1=7f1142600720 a2=7f1142600720 a3=722f7261762f2065 items=1 ppid=1 pid=1072 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="collectd" exe="/usr/sbin/collectd" subj=system_u:system_r:collectd_t:s0 key=(null) type=AVC msg=audit(1349714627.412:142): avc: denied { getattr } for pid=1072 comm="collectd" path="/usr/sbin/libvirtd" dev="dm-4" ino=12161 scontext=system_u:system_r:collectd_t:s0 tcontext=system_u:object_r:virtd_exec_t:s0 tclass=file ---- time->Mon Oct 8 16:45:07 2012 type=PATH msg=audit(1349714707.411:143): item=0 name="/usr/sbin/libvirtd" inode=12161 dev=fd:04 mode=0100755 ouid=0 ogid=0 rdev=00:00 obj=system_u:object_r:virtd_exec_t:s0 type=CWD msg=audit(1349714707.411:143): cwd="/var/lib/collectd" type=SYSCALL msg=audit(1349714707.411:143): arch=c000003e syscall=4 success=no exit=-13 a0=7f114ba71cac a1=7f1142600720 a2=7f1142600720 a3=722f7261762f2065 items=1 ppid=1 pid=1072 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="collectd" exe="/usr/sbin/collectd" subj=system_u:system_r:collectd_t:s0 key=(null) type=AVC msg=audit(1349714707.411:143): avc: denied { getattr } for pid=1072 comm="collectd" path="/usr/sbin/libvirtd" dev="dm-4" ino=12161 scontext=system_u:system_r:collectd_t:s0 tcontext=system_u:object_r:virtd_exec_t:s0 tclass=file
Created sos report for this one.
sosreport doesn't work: Creating compressed archive... tar: Options `-[0-7][lmh]' not supported by *this* tar Try `tar --help' or `tar --usage' for more information. sosreport is empty. Created 2 tar balls: /var/log/* and /etc/* Will try clean oVirt Node install + setenforce 0 after dinner....
Created attachment 623582 [details] /var/log/* All logfiles
Created attachment 623583 [details] /etc/* All files in /etc
David, what selinux policy do we need on fedora? Is this something new?
Created a brand new install using oVirt Node 2.5.2. Before registering to oVirt host: setenforce 0 Registered to oVirt Host, created local storage. 2012-10-08 18:11:50.478+0000: 5453: error : virNetClientProgramDispatchError:174 : unsupported configuration: spice secure channels set in XML configuration, but TLS is disabled in qemu.conf [root@localhost admin]# systemctl restart libvirtd.service; systemctl status libvirtd.service libvirtd.service - Virtualization daemon Loaded: loaded (/usr/lib/systemd/system/libvirtd.service; enabled) Active: active (running) since Mon, 08 Oct 2012 18:13:22 +0000; 11ms ago Main PID: 7017 (libvirtd) CGroup: name=systemd:/system/libvirtd.service └ 7017 /usr/sbin/libvirtd --listen systemctl restart libvirtd.service New virtual machines starts without problem. After enabling SELinux machine fails to start, disabling SELinux (setenforce 0) machine starts. All /var/log/* files en /etc/ attached once again.
Created attachment 623639 [details] clean install - selinux disabled - all /var/log/* files clean install - selinux disabled - all /var/log/* files
Created attachment 623640 [details] clean install - selinux disabled - all /etc/* files clean install - selinux disabled - all /etc/* files
bug 858832 is an f17 selinux problem starting sanlock which it appears is also happening here. The selinux package fixing the problem is linked from that bz. sanlock.log contains: set scheduler RR|RESET_ON_FORK priority 99 failed: Operation not permitted But, my larger question is why libvirt is using sanlock? I don't think rhev/ovirt uses sanlock with libvirt yet?
(In reply to comment #15) > bug 858832 is an f17 selinux problem starting sanlock which it appears is > also happening here. The selinux package fixing the problem is linked from > that bz. sanlock.log contains: > > set scheduler RR|RESET_ON_FORK priority 99 failed: Operation not permitted > > But, my larger question is why libvirt is using sanlock? I don't think > rhev/ovirt uses sanlock with libvirt yet? VDSM configures libvirt to use sanlock (even if later doesn't actually enables the leases). libvirt connects to sanlock when it starts the vm (even without leases) because it must be able to later on to dynamically attach leases if required (the use case is a little bit limited but it is correct, eg: a vm that starts with direct LUNS and then you hotplug a new disk that has a lease). No matter what the sanlock service wasn't running so even VDSM wouldn't be able to become the SPM. David, what is the required version for the selinux package?
comment in the other bz refers to selinux-policy-3.10.0-149.fc17.src.rpm
commit 623cc0365baea0bffa852aab30e8942750c14b9a Author: Federico Simoncelli <fsimonce> Date: Mon Oct 8 15:01:10 2012 -0400 specfile: require selinux-policy 3.10.0-149 Update to the newest selinux-policy package in fedora, among other general fixes it contains: - sanlock needs to send Kill Signals to non root process - update sanlock policy to solve all AVC's Bug-Url: https://bugzilla.redhat.com/show_bug.cgi?id=863980 Signed-off-by: Federico Simoncelli <fsimonce> Change-Id: I8502cb3b5fc84296059d1198675bf2491d606f14 http://gerrit.ovirt.org/#/c/8409/
The new seliux-policy (3.10.0-149) is required since vdsm-4.10.1-1.fc18.