libvirt users - Oct 2019 - Re: Transient permission denied errors when sending audit logs

Hi,

In kubevirt we are running into a strange permission problem on
libvirt-5.0. We see transient "Permission Denied" errors when
"virAuditSend"
wants to send an audit log. [1] shows the logs of one of these containers.
Here an example:

{"component":"virt-launcher","level":"warning","msg":"Failed
to send audit
message virt=kvm
vm=\"kubevirt-test-default_testvmit2pqrkrlrwbhptcjcs4n67jn6pjqvmtd7pkrpdmkrl5sldzs4rxr9zdg8m45jxz\"
uuid=56a33283-f6d7-4002-b188-1fed83186545 vm-ctx=+107:+107
img-ctx=+107:+107 model=dac: Permission
denied","pos":"virAuditSend:141","subcomponent":"libvirt","thread":"30","timestamp":"2019-10-08T23:58:40.651000Z"}

We recently switched in kubevirt to a dedicated selinux policy and remove
the general "privileged" flag from the containers where we run libvirt
in.
This is very likely related to it, but we can't make sense out of it,
because:

 * It randomly affects one out of a few hundred containers which we start
 * It is not bound to a specific node
 * It is only transient on that container. After a few denials libvirt can
just continue.
 * Sometimes it is accompanied with a transient "Permission denied" on
/dev/null from our code in that container (so not from something which
libvirt tries to do).

Has someone seen something like this before in different environments?

Best Regards,
Roman

[1]
https://storage.googleapis.com/kubevirt-prow/pr-logs/pull/kubevirt_kubevirt/2623/pull-kubevirt-e2e-os-3.11.0-crio/1181668456550895616/artifacts/pods/1_kubevirt-test-default_virt-launcher-testvmit2pqrkrlrwbhptcjcs4n67jn6pjqvmtd7pkrp75sjh-compute.log

On Thu, Oct 17, 2019 at 11:26:12AM +0200, Roman Mohr
wrote:
> Hi,
> 
> In kubevirt we are running into a strange permission problem on
> libvirt-5.0. We see transient "Permission Denied" errors when
"virAuditSend"
> wants to send an audit log. [1] shows the logs of one of these containers.
> Here an example:
> 
>
{"component":"virt-launcher","level":"warning","msg":"Failed
to send audit
> message virt=kvm
>
vm=\"kubevirt-test-default_testvmit2pqrkrlrwbhptcjcs4n67jn6pjqvmtd7pkrpdmkrl5sldzs4rxr9zdg8m45jxz\"
> uuid=56a33283-f6d7-4002-b188-1fed83186545 vm-ctx=+107:+107
> img-ctx=+107:+107 model=dac: Permission
>
denied","pos":"virAuditSend:141","subcomponent":"libvirt","thread":"30","timestamp":"2019-10-08T23:58:40.651000Z"}
> 
> We recently switched in kubevirt to a dedicated selinux policy and remove
> the general "privileged" flag from the containers where we run
libvirt in.
> This is very likely related to it, but we can't make sense out of it,
> because:
> 
>  * It randomly affects one out of a few hundred containers which we start
>  * It is not bound to a specific node
>  * It is only transient on that container. After a few denials libvirt can
> just continue.
The transient nature makes this really bizarre.

The error message above comes from the audit_log_user_message() call
that libvirt makes. This is implemented in libaudit.so using the
sendto() syscall on a netlink socket opened with

  socket(PF_NETLINK, SOCK_RAW, NETLINK_AUDIT);

So in terms of code being run there, there's very little - the EPERM
is coming back from the kernel when sending the message.

I'm not sure what scenario could cause this - perhaps the audit log
buffer in the kernel is full or something like that ?


>  * Sometimes it is accompanied with a transient "Permission
denied" on
> /dev/null from our code in that container (so not from something which
> libvirt tries to do).
> 
> Has someone seen something like this before in different environments?
Never seen anything like this reported before.

Regards,
Daniel
-- 
|: https://berrange.com      -o-    https://www.flickr.com/photos/dberrange :|
|: https://libvirt.org         -o-            https://fstop138.berrange.com :|
|: https://entangle-photo.org    -o-    https://www.instagram.com/dberrange :|

On Thu, Oct 17, 2019 at 11:34 AM Daniel P. Berrangé <berrange@redhat.com>
wrote:
> On Thu, Oct 17, 2019 at 11:26:12AM +0200, Roman Mohr wrote:
> > Hi,
> >
> > In kubevirt we are running into a strange permission problem on
> > libvirt-5.0. We see transient "Permission Denied" errors
when
> "virAuditSend"
> > wants to send an audit log. [1] shows the logs of one of these
> containers.
> > Here an example:
> >
> >
{"component":"virt-launcher","level":"warning","msg":"Failed
to send
> audit
> > message virt=kvm
> >
>
vm=\"kubevirt-test-default_testvmit2pqrkrlrwbhptcjcs4n67jn6pjqvmtd7pkrpdmkrl5sldzs4rxr9zdg8m45jxz\"
> > uuid=56a33283-f6d7-4002-b188-1fed83186545 vm-ctx=+107:+107
> > img-ctx=+107:+107 model=dac: Permission
> >
>
denied","pos":"virAuditSend:141","subcomponent":"libvirt","thread":"30","timestamp":"2019-10-08T23:58:40.651000Z"}
> >
> > We recently switched in kubevirt to a dedicated selinux policy and
remove
> > the general "privileged" flag from the containers where we
run libvirt
> in.
> > This is very likely related to it, but we can't make sense out of
it,
> > because:
> >
> >  * It randomly affects one out of a few hundred containers which we
start
> >  * It is not bound to a specific node
> >  * It is only transient on that container. After a few denials libvirt
> can
> > just continue.
>
> The transient nature makes this really bizarre.
>
> The error message above comes from the audit_log_user_message() call
> that libvirt makes. This is implemented in libaudit.so using the
> sendto() syscall on a netlink socket opened with
>
>   socket(PF_NETLINK, SOCK_RAW, NETLINK_AUDIT);
>
> So in terms of code being run there, there's very little - the EPERM
> is coming back from the kernel when sending the message.
>
> I'm not sure what scenario could cause this - perhaps the audit log
> buffer in the kernel is full or something like that ?
>
I will adjust our collectors to collect the selinux auditlog and dmesg.
Maybe I can see more there. Will update the thread when I have more
information.

>
>
> >  * Sometimes it is accompanied with a transient "Permission
denied" on
> > /dev/null from our code in that container (so not from something which
> > libvirt tries to do).
> >
> > Has someone seen something like this before in different environments?
>
> Never seen anything like this reported before.
>
Thanks Daniel.

Roman

>
> Regards,
> Daniel
> --
> |: https://berrange.com      -o-
> https://www.flickr.com/photos/dberrange :|
> |: https://libvirt.org         -o-
> https://fstop138.berrange.com :|
> |: https://entangle-photo.org    -o-
> https://www.instagram.com/dberrange :|
>