libvirt users - Feb 2020 - Re: USB-hotplugging fails with "failed to load cgroup BPF prog: Operation not permitted" on cgroups v2

Hi,

Quoting Pavel Hrdina (2020-01-21 12:53:49)
> On Mon, Jan 20, 2020 at 09:00:15PM +0100, Pol Van Aubel wrote:
> > Hi,
> > 
> > Quoting Pavel Hrdina (2020-01-20 14:29:36)
> > > On Sat, Jan 18, 2020 at 11:17:11PM +0100, Pol Van Aubel wrote:
> > > > Hi all,
> > > > 
> > > > I've disabled cgroups v1 on my system with the kernel
boot option
> > > > "systemd.unified_cgroup_hierarchy=1". Since doing
so, USB hotplugging
> > > > fails to work, seemingly due to a permissions problem with
BPF. Please
> > > > note that the technique I'm going to describe worked
just fine for
> > > > hotplugging USB devices to running domains until this
change.
> > > > Attaching / detaching USB devices when the domain is down
still works as
> > > > expected.
> > > > 
> > > > I get the same error when attaching a device in
virt-manager, as I do
> > > > when running the following command:
> > > > 
> > > > sudo virsh attach-device wenger /dev/stdin --persistent
<<END
> > > > <hostdev mode='subsystem' type='usb'
managed='yes'>
> > > >   <source startupPolicy='optional'>
> > > >     <vendor id='0x046d' />
> > > >     <product id='0xc215' />
> > > >   </source>
> > > > </hostdev>
> > > > END
> > > > 
> > > > This returns
> > > > error: Failed to attach device from /dev/stdin
> > > > error: failed to load cgroup BPF prog: Operation not
permitted
> > > > 
> > > > 
> > > > virt-manager returns basically the same error, but for
completeness'
> > > > sake, here it is:
> > > > 
> > > > failed to load cgroup BPF prog: Operation not permitted
> > > > 
> > > > Traceback (most recent call last):
> > > >   File
"/usr/share/virt-manager/virtManager/addhardware.py", line 1327, in
_add_device
> > > >     self.vm.attach_device(dev)
> > > >   File
"/usr/share/virt-manager/virtManager/object/domain.py", line 920, in
attach_device
> > > >     self._backend.attachDevice(devxml)
> > > >   File
"/usr/lib/python3.8/site-packages/libvirt.py", line 590, in
attachDevice
> > > >     if ret == -1: raise libvirtError
('virDomainAttachDevice() failed', dom=self)
> > > > libvirt.libvirtError: failed to load cgroup BPF prog:
Operation not permitted
> > > > 
> > > > 
> > > > Now, libvirtd is running as root, so I don't understand
why any
> > > > operation on BPF programs is not permitted. I've dug
into libvirt's code
> > > > a bit to see what is throwing this error and it boils down
to
> > > >
<https://github.com/libvirt/libvirt/blob/7d608469621a3fda72dff2a89308e68cc9fb4c9a/src/util/vircgroupv2devices.c#L292-L296>
> > > > and
> > > >
<https://github.com/libvirt/libvirt/blob/02bf7cc68bfc76242f02d23e73cad36618f3f790/src/util/virbpf.c#L54>
> > > > but I have no clue what that syscall is doing, so that's
where my
> > > > debugging capability basically ends.
> > > > 
> > > > Maybe this is something as simple as setting the right ACL
somewhere. I
> > > > haven't touched /etc/libvirt/qemu.conf except for
setting nvram. There
> > > > *is* something about cgroup_device_acl there but afaict
that's for
> > > > cgroups v1, when there was still a device cgroup controller.
Any help
> > > > would be greatly appreciated.
> > > > 
> > > > 
> > > > Domain log files:
> > > > Upon execution of the above commands, nothing gets added to
the domain
> > > > log in /var/log/qemu/wenger.log, so I've decided
they're likely
> > > > irrelevant to the issue. Please ask for any additional info
required.
> > > > 
> > > > 
> > > > System information:
> > > > Arch Linux, (normal) kernel 5.4.11
> > > > libvirt 5.10.0
> > > > qemu 4.2.0, using KVM.
> > > > Host system is x86_64 on an intel 5820k.
> > > > Guest system is probably irrelevant, but is Windows 10 on
the same.
> > > > 
> > > > 
> > > > Possibly relevant kernel build options:
> > > > $ zgrep BPF /proc/config.gz
> > > > [22:55:52]: zgrep BPF /proc/config.gz
> > > > 
> > > > CONFIG_CGROUP_BPF=y
> > > > CONFIG_BPF=y
> > > > CONFIG_BPF_SYSCALL=y
> > > > CONFIG_BPF_JIT_ALWAYS_ON=y
> > > > CONFIG_IPV6_SEG6_BPF=y
> > > > CONFIG_NETFILTER_XT_MATCH_BPF=m
> > > > # CONFIG_BPFILTER is not set
> > > > CONFIG_NET_CLS_BPF=m
> > > > CONFIG_NET_ACT_BPF=m
> > > > CONFIG_BPF_JIT=y
> > > > CONFIG_BPF_STREAM_PARSER=y
> > > > CONFIG_LWTUNNEL_BPF=y
> > > > CONFIG_HAVE_EBPF_JIT=y
> > > > CONFIG_BPF_EVENTS=y
> > > > # CONFIG_BPF_KPROBE_OVERRIDE is not set
> > > > # CONFIG_TEST_BPF is not set
> > > 
> > > Hi
> > > 
> > > I've installed clean archlinux to try this out and it works
as expected,
> > > I'm able to attach USB device into a VM.
> > > 
> > > My system env is mostly the same as yours except for kernel
version:
> > > 
> > >     kernel 5.4.13
> > >     libvirt 5.10.0
> > >     qemu 4.2.0, using KVM.
> > > 
> > > Please enable libvirt debug logs [1] and share the output with
us.
> > 
> > I've updated to 5.4.13 and created a barebones VM without storage
to
> > reproduce the behaviour. libvirtd debug logs are attached. There
appear
> > to be two BPF failures of the same BPF program (?). The first is on
line
> > 23209, which appears to be part of machine startup, and which I
don't
> > actually notice. The second one is where I manually add the USB
device,
> > on line 30599.
> > 
> > Thanks,
> 
> Thanks for the logs, but it did not help to figure out where the issue
> is.  I was hoping to see some error output from the syscall but the line
> that should contain it is empty:
> 
> 2020-01-20 19:47:15.589+0000: 8579: debug : virBPFLoadProg:78 :
> 
> Can you please check system logs and output of dmesg?
> 
> I've managed to run into this article [1] that explains that even if
you
> have all permissions and no SELinux you can still be blocked by
> something called kernel_lockdown and it should appear in dmesg.
> 
> Pavel
> 
> [1]
<https://gehrcke.de/2019/09/running-an-ebpf-program-may-require-lifting-the-kernel-lockdown/>
Unfortunately, nothing related to kernel lockdowns. My kernel sysrq also
doesn't seem to recognize x, and neither dmesg nor system journal
indicate the system is even booted with lockdowns. I don't run
Secure Boot, so that makes sense. I do get an audit message but that
doesn't really enlighten me any further; there's only 4 messages in the
journal related to this action.

Newlines added for clarity with line wrap.


Jan 21 23:29:33 victorinox libvirtd[790]: failed to load cgroup BPF
prog: Operation not permitted

Jan 21 23:29:33 victorinox audit[790]: VIRT_RESOURCE pid=790 uid=0
auid=4294967295 ses=4294967295 msg='virt=kvm resrc=cgroup reason=allow
vm="testvm" uuid=4da0d457-2e1f-4c53-87fc-530858e5e4cb
cgroup="/sys/fs/cgroup/machine.slice/machine-qemu\x2d1\x2dtestvm.scope/"
class=path path="/dev/bus/usb/002/011" rdev=BD:8A acl=rw
exe="/usr/bin/libvirtd" hostname=? addr=? terminal=? res=failed'

Jan 21 23:29:33 victorinox libvirtd[790]: Tried to close invalid fd 29

Jan 21 23:29:33 victorinox kernel: audit: type=2501
audit(1579645773.264:202): pid=790 uid=0 auid=4294967295 ses=4294967295
msg='virt=kvm resrc=cgroup reason=allow vm="testvm"
uuid=4da0d457-2e1f-4c53-87fc-530858e5e4cb
cgroup="/sys/fs/cgroup/machine.slice/machine-qemu\x2d1\x2dtestvm.scope/"
class=path path="/dev/bus/usb/002/011" rdev=BD:8A acl=rw
exe="/usr/bin/libvirtd" hostname=? addr=? terminal=? res=failed'


I honestly don't know how to even begin debugging what's happening, what
the reason for the rejection is.

-- Pol


P.S. My previous message got rejected from the list because I wasn't
thinking and attached 3MiB of debug logs. Since Pavel hasn't found what
he was looking for in them I figure it makes little sense to upload and
link them, the rest of the message is included inline.

Hi,

Quoting Pol Van Aubel (2020-01-21 23:41:48)
> Hi,
> 
> Quoting Pavel Hrdina (2020-01-21 12:53:49)
> > Thanks for the logs, but it did not help to figure out where the issue
> > is.  I was hoping to see some error output from the syscall but the
line
> > that should contain it is empty:
> > 
> > 2020-01-20 19:47:15.589+0000: 8579: debug : virBPFLoadProg:78 :
> > 
> > Can you please check system logs and output of dmesg?
> > 
> > I've managed to run into this article [1] that explains that even
if you
> > have all permissions and no SELinux you can still be blocked by
> > something called kernel_lockdown and it should appear in dmesg.
> > 
> > Pavel
> > 
> > [1]
<https://gehrcke.de/2019/09/running-an-ebpf-program-may-require-lifting-the-kernel-lockdown/>
> 
> Unfortunately, nothing related to kernel lockdowns. My kernel sysrq also
> doesn't seem to recognize x, and neither dmesg nor system journal
> indicate the system is even booted with lockdowns. I don't run
> Secure Boot, so that makes sense. I do get an audit message but that
> doesn't really enlighten me any further; there's only 4 messages in
the
> journal related to this action.
> 
> <snip>
> 
> I honestly don't know how to even begin debugging what's happening,
what
> the reason for the rejection is.
I've spent a long afternoon reading into BPF, checking that I'm really
running this as root, with CAP_SYS_ADMIN, etc, and am drawing a blank.
Everything I'm looking at is telling me this *should* work, but it
doesn't.

Does anyone have a suggestion of how to either efficiently debug this
issue (I'm not too familiar with tracing, but figuring out where the
rejection actually happens might help?), or where to put the question
instead?

-- Pol

Hi,

Top-posting a quick update to this: it has magically started working
with linux 5.6.10. Didn't on 5.5.13 nor 5.4.35-lts. So the problem has
been solved, even though I never got to trace it to its source.

-- Pol


Quoting Pol Van Aubel (2020-02-15 17:16:14)
> Hi,
> 
> Quoting Pol Van Aubel (2020-01-21 23:41:48)
> > Hi,
> > 
> > Quoting Pavel Hrdina (2020-01-21 12:53:49)
> > > Thanks for the logs, but it did not help to figure out where the
issue
> > > is.  I was hoping to see some error output from the syscall but
the line
> > > that should contain it is empty:
> > > 
> > > 2020-01-20 19:47:15.589+0000: 8579: debug : virBPFLoadProg:78 :
> > > 
> > > Can you please check system logs and output of dmesg?
> > > 
> > > I've managed to run into this article [1] that explains that
even if you
> > > have all permissions and no SELinux you can still be blocked by
> > > something called kernel_lockdown and it should appear in dmesg.
> > > 
> > > Pavel
> > > 
> > > [1]
<https://gehrcke.de/2019/09/running-an-ebpf-program-may-require-lifting-the-kernel-lockdown/>
> > 
> > Unfortunately, nothing related to kernel lockdowns. My kernel sysrq
also
> > doesn't seem to recognize x, and neither dmesg nor system journal
> > indicate the system is even booted with lockdowns. I don't run
> > Secure Boot, so that makes sense. I do get an audit message but that
> > doesn't really enlighten me any further; there's only 4
messages in the
> > journal related to this action.
> > 
> > <snip>
> > 
> > I honestly don't know how to even begin debugging what's
happening, what
> > the reason for the rejection is.
> 
> I've spent a long afternoon reading into BPF, checking that I'm
really
> running this as root, with CAP_SYS_ADMIN, etc, and am drawing a blank.
> Everything I'm looking at is telling me this *should* work, but it
> doesn't.
> 
> Does anyone have a suggestion of how to either efficiently debug this
> issue (I'm not too familiar with tracing, but figuring out where the
> rejection actually happens might help?), or where to put the question
> instead?
> 
> -- Pol
> 
>