Libvirt can't create new VM (logging issue)

[spacimek]

Describe the bug

I would like to set up rather permanent Windows 11 VM, so I am trying to use libvirt along with its VM Manager.

Here's the error:
Unable to complete install: 'can't connect to virtlogd: Unable to open file: /var/log/libvirt/qemu/XPS.log: Permission denied'

Traceback (most recent call last):
File "/usr/share/virt-manager/virtManager/asyncjob.py", line 72, in cb_wrapper
callback(asyncjob, *args, **kwargs)
File "/usr/share/virt-manager/virtManager/createvm.py", line 2008, in _do_async_install
installer.start_install(guest, meter=meter)
File "/usr/share/virt-manager/virtinst/install/installer.py", line 695, in start_install
domain = self._create_guest(
^^^^^^^^^^^^^^^^^^^
File "/usr/share/virt-manager/virtinst/install/installer.py", line 637, in _create_guest
domain = self.conn.createXML(initial_xml or final_xml, 0)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/lib64/python3.12/site-packages/libvirt.py", line 4529, in createXML
raise libvirtError('virDomainCreateXML() failed')
libvirt.libvirtError: can't connect to virtlogd: Unable to open file: /var/log/libvirt/qemu/XPS.log: Permission denied

I tried to change the dir to 777, I even tried to touch the file, but it didn't help:
❯ ls -ltra /var/log/libvirt/qemu/
total 0
drwxrwxrwx. 1 root root 8 May 7 14:29 ..
-rw-r--r--. 1 slavek slavek 0 May 7 14:32 XPS.log
drwxrwxrwx. 1 root root 18 May 7 14:32 .

I tried to go with manual setup as well as semi-automated ISO setup, both cases gave the same error.

What did you expect to happen?

I expect libvirt to start making my VM!

Output of rpm-ostree status

State: idle
AutomaticUpdates: stage; rpm-ostreed-automatic.timer: last run 1 day 1h ago
Deployments:
  ostree-image-signed:docker://ghcr.io/ublue-os/aurora-dx:latest
                   Digest: sha256:5d64652fe35ea16c895962b31b4c41cfaeab904c392d99cce67cd3e99640ce83
                  Version: 40.20240506.0 (2024-05-06T16:53:28Z)
                     Diff: 12 upgraded

● ostree-image-signed:docker://ghcr.io/ublue-os/aurora-dx:latest
                   Digest: sha256:8f5d5c70a409c581c25fc3d7bcc0be565a4bcc237030022fa63050244b7bfad2
                  Version: 40.20240505.0 (2024-05-05T16:51:55Z)

  ostree-image-signed:docker://ghcr.io/ublue-os/aurora-dx:latest
                   Digest: sha256:e9d1f50e54f031f14c9edc34ecbff4e1762e46670694618b055af60830409c4d
                  Version: 40.20240428.0 (2024-04-29T02:07:21Z)

Extra information or context

I have disabled root account for the installation, if that makes any difference.

[castrojo]

Can you paste in the output of the groups command?

[spacimek]

❯ groups
slavek wheel docker incus-admin lxd libvirt

[m2Giles]

You have the correct groups.

Since 777 perms are also not resolving the issue. Can you temporarily try setting SELinux to permissive mode and try creating your VM.

[spacimek]

Thanks for the tip, but that doesn't seem to change anything:

❯ cat /etc/selinux/config | grep SELINUX=
SELINUX=permissive

Still:
libvirt.libvirtError: can't connect to virtlogd: Unable to open file: /var/log/libvirt/qemu/win11.log: Permission denied

I even tried to touch that log and change to 777, to make sure he's not using some weird user.

In any case, I can prepare the storage volume:

❯ sudo ls -ltra /var/lib/libvirt/images
total 96204
drwxr-xr-x. 1 root root 20 May 7 14:22 ..
drwx--x--x. 1 root root 22 May 7 23:19 .
-rw-------. 1 root root 644343660544 May 7 23:19 win11.qcow2

...just it's not usable.

[spacimek]

It seems to be broader F40 issue:
https://discussion.fedoraproject.org/t/cannot-launch-libvirt-virtual-machines-after-upgrade-to-fedora-40/112533

I am not sure how often are you taking F40 images for baseline? This one seems to be resolved since 6 days ago...

[spacimek]

This is the temporary workaround I applied to get things started:
https://discussion.fedoraproject.org/t/virt-manager-quit-working-ibvirterror-cant-connect-to-virtlogd/113631/4

[m2Giles]

We pull from upstream each day.

I'm curious why permissive mode failed, it should of just logged the violation instead of failing.

restorecon should be the fix in this situation if the file tree at that location has the wrong labels or in this case missing labels.

After a restorecon I'm assuming it's now working. Since it's applied to /var it will persist through reboots.

For timeline of the bug, did you do a fresh install of f40? Roughly when?

[spacimek]

Yes, indeed. All seems to be working well. I have installed my Aurora 3 days ago - a day after 2.6.0 was released (I have Framework 16, so I was waiting for some FW-related goodies, to make sure all works well).

[spacimek]

Well, I better correct myself, as after reboot I simply could not get back to OS (my root is disabled, so I could not even get to terminal to fix things). This might be due to disabling SElinux (as I ran setenforce 0), was probably not a good idea to keep it that way... not sure, simply need to reinstall.

[m2Giles]

Did you do setenforce 0 while running or did you do kernel argument to disable SELinux?

Setenforce 0 will only put the system into permissive mode.

Bigger concern is what restorecon did you do

[m2Giles]

Reinstall will likely have the same bug with /var/log/libvirt not having right labels.

When you do the restorecon. Ensure that it is only on that directory and below.

Do not do the auto relabel or attempt to relabel / recursively.

[spacimek]

OK, sure. Thanks a lot for the tips and you might be right. I will wait for a new image - I guess it will still come this week - and see, maybe I get lucky and the fix will be pulled from upstream. Kinoite might have received it a bit later than stock F40, so it might come with fresh ISO build.

[spacimek]

Did you do setenforce 0 while running or did you do kernel argument to disable SELinux?

Setenforce 0 will only put the system into permissive mode.

Bigger concern is what restorecon did you do

You are right, setenforce is temporary, but I have updated also the file to permissive and left it there, some processes might not like that. But it can indeed be rather issue with restorecon. I'll be testing it better next time.

[m2Giles]

On my Aurora-dx 40 install (not rebase from 39).

/var/log/libvirt is missing until you create your first vm. The directory and log file were then created with the correct file labels.

So either this was a regression for your install or the files were created somehow prior to SELinux being enabled.

[spacimek]

Thanks a lot for checking @m2Giles ! My further suspicion was that I might need to keep root enabled. Maybe he can't deal with elevated privileges? Not sure, but I will try again with root enabled once 2.7.0 is out... It's quite bad I don't have a way to recover without root, so I better keep it anyways for now.

[m2Giles]

I have root disabled and use my account with sudo

[spacimek]

@m2Giles How did you create your first VM? Should I follow some manual process?

I have reinstalled Aurora-DX 40 fresh again, but the issue is still there. I tried to go with enabled root this time, but no difference - I can't enable virtual network and he can't create any log:

Unable to complete install: 'can't connect to virtlogd: Unable to open file: /var/log/libvirt/qemu/win11.log: Permission denied'

Traceback (most recent call last):
File "/usr/share/virt-manager/virtManager/asyncjob.py", line 72, in cb_wrapper
callback(asyncjob, *args, **kwargs)
File "/usr/share/virt-manager/virtManager/createvm.py", line 2008, in _do_async_install
installer.start_install(guest, meter=meter)
File "/usr/share/virt-manager/virtinst/install/installer.py", line 695, in start_install
domain = self._create_guest(
^^^^^^^^^^^^^^^^^^^
File "/usr/share/virt-manager/virtinst/install/installer.py", line 637, in _create_guest
domain = self.conn.createXML(initial_xml or final_xml, 0)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/lib64/python3.12/site-packages/libvirt.py", line 4529, in createXML
raise libvirtError('virDomainCreateXML() failed')
libvirt.libvirtError: can't connect to virtlogd: Unable to open file: /var/log/libvirt/qemu/win11.log: Permission denied

The network is failing for similar reason:

libvirt.libvirtError: cannot create directory /var/lib/libvirt/dnsmasq: Permission denied

Funny enough, I still have no issues with preparing disk image in /var/lib/libvirt/images

[bketelsen]

the restorecon command linked above fixed my issues too

[m2Giles]

I created an alpine VM with the defaults.

[spacimek]

I am getting similar stuff also from CLI:

❯ sudo virsh net-start default
error: Failed to start network default
error: cannot create directory /var/lib/libvirt/dnsmasq: Permission denied

❯ ls -ltra /var/lib/libvirt/
total 0
drwxr-xr-x. 1 root root 20 May 14 13:17 .
drwx--x--x. 1 root root 22 May 14 13:40 images
drwxr-xr-x. 1 root root 882 May 14 13:40 ..
drwxr-xr-x. 1 qemu qemu 68 May 14 15:15 qemu

❯ sudo cat /etc/libvirt/qemu/networks/default.xml

<network>
  <name>default</name>
  <uuid>6a5b27e4-254b-461f-93b3-e76ec354f019</uuid>
  <forward mode='nat'/>
  <bridge name='virbr0' stp='on' delay='0'/>
  <mac address='52:54:00:e3:b0:85'/>
  <ip address='192.168.122.1' netmask='255.255.255.0'>
    <dhcp>
      <range start='192.168.122.2' end='192.168.122.254'/>
    </dhcp>
  </ip>
</network>

[m2Giles]

I would do the restorecon on the directory. The files are correct but for whatever reason are not labeled correctly.

To see the SELinux file labels use ls -lZ

If we need to respin ISOs, we can do that.

[spacimek]

I tried at least to go without turning off SElinux... but so far:

sudo chmod 700 /var/log/libvirt/qemu

sudo restorecon -rv /var/log/libvirt/

Relabeled /var/log/libvirt from system_u:object_r:var_log_t:s0 to system_u:object_r:virt_log_t:s0
Relabeled /var/log/libvirt/qemu from system_u:object_r:var_log_t:s0 to system_u:object_r:virt_log_t:s0

sudo restorecon -rv /var/lib/libvirt/

Relabeled /var/lib/libvirt from system_u:object_r:var_lib_t:s0 to system_u:object_r:virt_var_lib_t:s0
Relabeled /var/lib/libvirt/qemu from system_u:object_r:var_lib_t:s0 to system_u:object_r:qemu_var_run_t:s0
Relabeled /var/lib/libvirt/qemu/save from system_u:object_r:var_lib_t:s0 to system_u:object_r:qemu_var_run_t:s0
Relabeled /var/lib/libvirt/qemu/snapshot from system_u:object_r:var_lib_t:s0 to system_u:object_r:qemu_var_run_t:s0
Relabeled /var/lib/libvirt/qemu/checkpoint from system_u:object_r:var_lib_t:s0 to system_u:object_r:qemu_var_run_t:s0
Relabeled /var/lib/libvirt/qemu/dump from system_u:object_r:var_lib_t:s0 to system_u:object_r:qemu_var_run_t:s0
Relabeled /var/lib/libvirt/qemu/nvram from system_u:object_r:var_lib_t:s0 to system_u:object_r:qemu_var_run_t:s0
Relabeled /var/lib/libvirt/qemu/nvram/win11_VARS.qcow2 from system_u:object_r:var_lib_t:s0 to system_u:object_r:qemu_var_run_t:s0
Relabeled /var/lib/libvirt/qemu/ram from system_u:object_r:var_lib_t:s0 to system_u:object_r:qemu_var_run_t:s0
Relabeled /var/lib/libvirt/images from system_u:object_r:var_lib_t:s0 to system_u:object_r:virt_image_t:s0
Relabeled /var/lib/libvirt/images/win11.qcow2 from system_u:object_r:var_lib_t:s0 to system_u:object_r:virt_image_t:s0

sudo virsh net-start default

Network default started

So here at least the network is catching up and all relevant dirs seem to have proper rights (comparing to F39).

However installation is giving me now:

libvirt.libvirtError: internal error: Could not run '/usr/bin/swtpm_setup'. exitstatus: 1; Check error log '/var/log/swtpm/libvirt/qemu/win11-swtpm.log' for details.

❯ sudo cat /var/log/swtpm/libvirt/qemu/win11-swtpm.log
swtpm at /usr/bin/swtpm does not support TPM 2
swtpm at /usr/bin/swtpm does not support TPM 1.2

According to F40 forum from 8 days ago:

swtpm 0.8.1-9 solves all issues we have documented

Not sure how can I check my version:

❯ /usr/bin/swtpm --version
TPM emulator version 0.8.1, Copyright (c) 2014-2022 IBM Corp. and others

[spacimek]

OK, so I can confirm that after reboot, I can start Win11 VM. Probably just needed to properly label the processes as well (not only the dirs).

@m2Giles For the reference (if we want to fix things in ISO), here are my current privileges:

bash-5.2# ls -lZ /var/log/libvirt/qemu/
total 16
-rw-------. 1 root root system_u:object_r:virt_log_t:s0 13914 May 14 17:02 win11.log

bash-5.2# ls -lZd /var/log/libvirt/qemu/
drwx------. 1 root root system_u:object_r:virt_log_t:s0 18 May 14 15:40 /var/log/libvirt/qemu/

bash-5.2# ls -lZd /var/log/libvirt/
drwxr-xr-x. 1 root root system_u:object_r:virt_log_t:s0 8 May 14 13:28 /var/log/libvirt/

SElinux seems to be happy. If we want to be fully compatible with what F39 had, we can also

chmod 700 /var/log/libvirt/

Still, will keep this issue for a little bit. I don't like to have this upon the boot:

[FAILED] Failed to start systemd-modules-load.services - Load Kernel modules

Probably is this one:

May 14 17:11:36 systemd[1]: Failed to start displaylink.service - DisplayLink Manager Service.
May 14 17:11:36 modprobe[8910]: modprobe: ERROR: could not insert 'evdi': Key was rejected by service

[m2Giles]

You don't have the MOK installed for secureboot.

Unsigned Out of tree modules will be rejected when secureboot is enabled.