Re: Apparmor (and other) Issues

[Stefano Brivio <sbrivio@redhat.com>]

On Sun, 02 Feb 2025 14:21:49 +0000
Prafulla Giri <prafulla.giri@protonmail.com> wrote:

> On Saturday, February 1st, 2025 at 2:05 AM, Stefano Brivio <sbrivio@redhat.com> wrote:
> 
> > On Thu, 30 Jan 2025 10:05:14 +0000
> > Prafulla Giri prafulla.giri@protonmail.com wrote:
> >   
> > > I didn't have auditd installed on Debian and installed it, and
> > > running everything with the default auditd config (with my Apparmor
> > > disabled for passt, as mentioned previously) does not result in
> > > anything. Do I have to configure auditd manually? Any pointers on
> > > that, please?  
> > 
> > 
> > No, the default configuration is just fine. But you should re-enable
> > AppArmor for passt so that we can see meaningful messages in the logs.
> >   
> The following is the output of grep-ping 'passt' after re-enforcing the apparmor config and trying to start a VM:
> $ grep passt /var/log/audit/audit.log # Debian Trixie
> type=AVC msg=audit(1738501259.829:124): apparmor="STATUS" operation="profile_load" profile="unconfined" name="passt" pid=1935 comm="apparmor_parser"
> type=AVC msg=audit(1738501309.118:135): apparmor="DENIED" operation="file_mmap" class="file" profile="passt" name="/usr/bin/passt" pid=2030 comm="passt" requested_mask="r" denied_mask="r" fsuid=1000 ouid=0\x1dFSUID="larryboy" OUID="root"
> type=SYSCALL msg=audit(1738501309.118:135): arch=c000003e syscall=59 success=no exit=-13 a0=7faf24035fc0 a1=7faf24035210 a2=7ffc063280d0 a3=0 items=0 ppid=1964 pid=2030 auid=1000 uid=1000 gid=1000 euid=1000 suid=1000 fsuid=1000 egid=1000 sgid=1000 fsgid=1000 tty=(none) ses=1 comm="passt" exe="/usr/bin/passt" subj=passt key=(null)\x1dARCH=x86_64 SYSCALL=execve AUID="larryboy" UID="larryboy" GID="larryboy" EUID="larryboy" SUID="larryboy" FSUID="larryboy" EGID="larryboy" SGID="larryboy" FSGID="larryboy"
> type=ANOM_ABEND msg=audit(1738501309.118:136): auid=1000 uid=1000 gid=1000 ses=1 subj=passt pid=2030 comm="passt" exe="/usr/bin/passt" sig=11 res=1\x1dAUID="larryboy" UID="larryboy" GID="larryboy"

System call number 59 (this seems to be x86_64) is "execve":

  $ ausyscall 59
  execve

and this seems to be libvirt failing to execute passt itself, but:

  https://gitlab.com/libvirt/libvirt/-/blob/0264a7704ada52f686cafe8f6402d5b60f9f0fc4/src/security/apparmor/libvirt-qemu.in#L195

Do you see the libvirtd profile loaded if you run 'aa-status'?

Do you have this line:

  /usr/bin/passt Cx -> passt,

in /etc/apparmor.d/abstractions/libvirt-qemu? I wonder if something
bad happened during installation.

Can you perhaps grep a bit before and after those messages (say, grep
-A5 -B5) to see if we spot something else related to libvirt?

> type=AVC msg=audit(1738501923.727:148): apparmor="DENIED" operation="file_mmap" class="file" profile="passt" name="/usr/bin/passt" pid=2088 comm="passt" requested_mask="r" denied_mask="r" fsuid=1000 ouid=0\x1dFSUID="larryboy" OUID="root"
> type=SYSCALL msg=audit(1738501923.727:148): arch=c000003e syscall=59 success=no exit=-13 a0=7ff564035d40 a1=7ff564039d00 a2=7fffe9aa1de0 a3=0 items=0 ppid=2060 pid=2088 auid=1000 uid=1000 gid=1000 euid=1000 suid=1000 fsuid=1000 egid=1000 sgid=1000 fsgid=1000 tty=(none) ses=1 comm="passt" exe="/usr/bin/passt" subj=passt key=(null)\x1dARCH=x86_64 SYSCALL=execve AUID="larryboy" UID="larryboy" GID="larryboy" EUID="larryboy" SUID="larryboy" FSUID="larryboy" EGID="larryboy" SGID="larryboy" FSGID="larryboy"
> type=ANOM_ABEND msg=audit(1738501923.727:149): auid=1000 uid=1000 gid=1000 ses=1 subj=passt pid=2088 comm="passt" exe="/usr/bin/passt" sig=11 res=1\x1dAUID="larryboy" UID="larryboy" GID="larryboy"
> type=AVC msg=audit(1738502301.651:174): apparmor="DENIED" operation="file_mmap" class="file" profile="passt" name="/usr/bin/passt" pid=2145 comm="passt" requested_mask="r" denied_mask="r" fsuid=1000 ouid=0\x1dFSUID="larryboy" OUID="root"
> type=SYSCALL msg=audit(1738502301.651:174): arch=c000003e syscall=59 success=no exit=-13 a0=7fe208034ce0 a1=7fe208034350 a2=7fffd2e60120 a3=0 items=0 ppid=2117 pid=2145 auid=1000 uid=1000 gid=1000 euid=1000 suid=1000 fsuid=1000 egid=1000 sgid=1000 fsgid=1000 tty=(none) ses=1 comm="passt" exe="/usr/bin/passt" subj=passt key=(null)\x1dARCH=x86_64 SYSCALL=execve AUID="larryboy" UID="larryboy" GID="larryboy" EUID="larryboy" SUID="larryboy" FSUID="larryboy" EGID="larryboy" SGID="larryboy" FSGID="larryboy"
> type=ANOM_ABEND msg=audit(1738502301.651:175): auid=1000 uid=1000 gid=1000 ses=1 subj=passt pid=2145 comm="passt" exe="/usr/bin/passt" sig=11 res=1\x1dAUID="larryboy" UID="larryboy" GID="larryboy"
> 
> > > $ passt -f -d # on Debian Testing/Trixie
> > > 0.0016: No interfaces with usable IPv6 routes
> > > 0.0017: Failed to detect external interface for IPv6
> > > 0.0028: UNIX domain socket bound at /tmp/passt_1.socket
> > > 0.0029: Template interface: enp1s0 (IPv4)
> > > 0.0029: MAC:
> > > 0.0029: host: 9a:55:9a:55:9a:55
> > > 0.0029: NAT to host 127.0.0.1: 192.168.100.1
> > > 0.0029: DHCP:
> > > 0.0029: assign: 192.168.100.157
> > > 0.0029: mask: 255.255.255.0
> > > 0.0029: router: 192.168.100.1
> > > 0.0029: DNS:
> > > 0.0029: 192.168.100.1  
> > 
> > 
> > So, judging from this configuration, it looks like we advertise to
> > the guest (via DHCP) 192.168.100.1 as resolver (copied from the host),
> > and when we receive packets from the guest for 192.168.100.1, we'll
> > re-map them to the host.
> > 
> > Nothing strange so far, systemd-resolved is running on the host, it
> > should get our queries and reply to them.
> >   
> > > $ cat /etc/resolv.conf # On Debian Trixie
> > > # This is /run/systemd/resolve/resolv.conf managed by
> > > man:systemd-resolved(8). [...]
> > > nameserver 192.168.100.1
> > > search .
> > > $ cat /etc/resolv.conf # On a Debian 11 OS
> > > # Generated by NetworkManager
> > > nameserver 192.168.100.1
> > > 
> > > Also the output of `resolvectl status` for good measure:
> > > # On Fedora 41
> > > Global
> > > Protocols: LLMNR=resolve -mDNS -DNSOverTLS
> > > DNSSEC=no/unsupported resolv.conf mode: stub
> > > 
> > > Link 2 (wlp0s20f3)
> > > Current Scopes: DNS LLMNR/IPv4 LLMNR/IPv6
> > > Protocols: +DefaultRoute LLMNR=resolve -mDNS -DNSOverTLS
> > > DNSSEC=no/unsupported Current DNS Server: 192.168.100.1
> > > DNS Servers: 192.168.100.1
> > > 
> > > # On Debian Trixie
> > > Global
> > > Protocols: +LLMNR +mDNS -DNSOverTLS DNSSEC=no/unsupported
> > > resolv.conf mode: uplink
> > > 
> > > Link 2 (enp1s0)
> > > Current Scopes: DNS LLMNR/IPv4 LLMNR/IPv6
> > > Protocols: +DefaultRoute +LLMNR -mDNS -DNSOverTLS
> > > DNSSEC=no/unsupported DNS Servers: 192.168.100.1
> > > Default Route: yes  
> > 
> > 
> > Everything as expected here, I don't see any obvious reason why
> > systemd-resolved should discard our queries.
> >   
> > > The log from Debian Trixie host for VM1:
> > > passt 0.0~git20250121.4f2c8e7-1: /usr/bin/passt.avx2 (6428)
> > > 0.0017: info: No interfaces with usable IPv6 routes
> > > 0.0029: info: UNIX domain socket bound at
> > > /run/user/1000/libvirt/qemu/run/passt/2-vm1-net0.socket 0.0030: info:
> > > Template interface: enp1s0 (IPv4) 0.0030: info: MAC:
> > > 0.0030: info: host: 9a:55:9a:55:9a:55
> > > 0.0030: info: NAT to host 127.0.0.1: 192.168.100.1
> > > 0.0030: info: DHCP:
> > > 0.0031: info: assign: 192.168.100.157
> > > 0.0031: info: mask: 255.255.255.0
> > > 0.0031: info: router: 192.168.100.1
> > > 0.0031: info: DNS:
> > > 0.0031: info: 192.168.100.1
> > > 0.0031: info: DNS search list:
> > > 0.0031: info: .
> > > 0.0066: info:
> > > You can now start qemu (>= 7.2, with commit 13c6be96618c):
> > > 0.0066: info: kvm ... -device virtio-net-pci,netdev=s -netdev
> > > stream,id=s,server=off,addr.type=unix,addr.path=/run/user/1000/libvirt/qemu/run/passt/2-vm1-net0.socket
> > > 0.0066: info: or qrap, for earlier qemu versions: 0.0066: info:
> > > ./qrap 5 kvm ... -net socket,fd=5 -net nic,model=virtio 0.0617:
> > > info: accepted connection from PID 0 38.6257: info: DHCP: offer
> > > to discover 38.6257: info: from 52:54:00:a0:e1:7c
> > > 38.6471: info: DHCP: ack to request
> > > 38.6471: info: from 52:54:00:a0:e1:7c
> > > 451.4989: info: Client connection closed, exiting  
> > 
> > 
> > Unfortunately libvirt doesn't let us enable more verbose logging. I
> > hoped to see DNS queries there, but without --debug given to passt,
> > that won't work.
> > 
> > Another idea: pasta(1) does the same job as passt(1) (it's the same
> > code and same binary) and it's intended for containers, but it has a
> > stand-alone mode that can probably help us to debug this, because it's
> > a network namespace that will look like your guest, and it can also
> > take packet captures.
> > 
> > What happens if you run:
> > 
> > pasta --config-net --trace --pcap /tmp/dns.pcap -- nslookup fsf.org
> > 
> > ?  
> This one errors out. dns.pcap is attached.
> $ pasta --config-net --trace --pcap /tmp/dns.pcap -- nslookup fsf.org # Debian Trixie/Testing
> 0.0015: No interfaces with usable IPv6 routes
> 0.0015: Failed to detect external interface for IPv6
> 0.0073: Template interface: enp1s0 (IPv4)
> 0.0073: Namespace interface: enp1s0
> 0.0074: MAC:
> 0.0074:     host: 9a:55:9a:55:9a:55
> 0.0074:     NAT to host 127.0.0.1: 192.168.100.1
> 0.0074: DHCP:
> 0.0074:     assign: 192.168.100.157
> 0.0074:     mask: 255.255.255.0
> 0.0075:     router: 192.168.100.1
> 0.0075: DNS:
> 0.0075:     192.168.100.1
> 0.0076: DNS search list:
> 0.0076:     .
> 0.0146: SO_PEEK_OFF supported
> 0.0146: TCP_INFO tcpi_snd_wnd field  supported
> 0.0146: TCP_INFO tcpi_bytes_acked field  supported
> 0.0146: TCP_INFO tcpi_min_rtt field  supported
> 0.0147: Saving packet capture to /tmp/dns.pcap
> 0.0197: pasta: epoll event on /dev/net/tun device 16 (events: 0x00000001)
> 0.0371: pasta: epoll event on /dev/net/tun device 16 (events: 0x00000001)
> 0.0372: pasta: epoll event on /dev/net/tun device 16 (events: 0x00000001)
> 0.0372: tap: protocol 17, 192.168.100.157:41892 -> 192.168.100.1:53 (1 packet)
> 0.0372: Flow 0 (NEW): FREE -> NEW
> 0.0372: Flow 0 (INI): NEW -> INI
> 0.0372: Flow 0 (INI): TAP [192.168.100.157]:41892 -> [192.168.100.1]:53 => ?
> 0.0372: Flow 0 (TGT): INI -> TGT
> 0.0373: Flow 0 (TGT): TAP [192.168.100.157]:41892 -> [192.168.100.1]:53 => HOST [0.0.0.0]:41892 -> [127.0.0.1]:53
> 0.0373: Flow 0 (UDP flow): TGT -> TYPED
> 0.0373: Flow 0 (UDP flow): TAP [192.168.100.157]:41892 -> [192.168.100.1]:53 => HOST [0.0.0.0]:41892 -> [127.0.0.1]:53
> 0.0373: Flow 0 (UDP flow): Side 0 hash table insert: bucket: 31049
> 0.0374: Flow 0 (UDP flow): TYPED -> ACTIVE
> 0.0374: Flow 0 (UDP flow): TAP [192.168.100.157]:41892 -> [192.168.100.1]:53 => HOST [0.0.0.0]:41892 -> [127.0.0.1]:53
> 0.0374: pasta: epoll event on UDP reply socket 95 (events: 0x00000008)
> 0.0374: ICMP error on UDP socket 95: Connection refused

Ouch. I just sent a patch for this, you can test it by checking out
passt locally:

  git clone git://passt.top/passt; cd passt

applying it (you might need to install 'b4'):

  b4 shazam
  https://archives.passt.top/passt-dev/20250203082210.2114348-1-sbrivio@redhat.com/

then:

  make

and ./pasta --config-net --trace --pcap /tmp/dns.pcap -- nslookup
fsf.org

You can also install it to /usr/local with 'make install', it's just a
couple of files and will uninstall cleanly with 'make uninstall' if
needed. Note that AppArmor profiles don't apply to binaries under
/usr/local/bin.

> [...]
>
> This is rather strange: from the shell I successfully managed to `ping fsf.org` and `ping gnu.org`.

That's because they were already cached on your host at this point (I
suppose by systemd-resolved) and ping didn't need to resolve anything,
just call getaddrinfo() and get the addresses back. There's no UDP at
all in the output below:

> I went back and ran
> $ pasta --config-net --trace --pcap /tmp/ping.pcap -- ping -c 5 fsf.org # and the following output followed (ping.pcap is also attached)
> 
> 0.0013: No interfaces with usable IPv6 routes
> 0.0013: Failed to detect external interface for IPv6
> 0.0091: Template interface: enp1s0 (IPv4)
> 0.0091: Namespace interface: enp1s0
> 0.0092: MAC:
> 0.0092:     host: 9a:55:9a:55:9a:55
> 0.0092:     NAT to host 127.0.0.1: 192.168.100.1
> 0.0092: DHCP:
> 0.0092:     assign: 192.168.100.157
> 0.0093:     mask: 255.255.255.0
> 0.0093:     router: 192.168.100.1
> 0.0093: DNS:
> 0.0093:     192.168.100.1
> 0.0093: DNS search list:
> 0.0094:     .
> 0.0161: SO_PEEK_OFF supported
> 0.0161: TCP_INFO tcpi_snd_wnd field  supported
> 0.0161: TCP_INFO tcpi_bytes_acked field  supported
> 0.0161: TCP_INFO tcpi_min_rtt field  supported
> 0.0162: Saving packet capture to /tmp/ping.pcap
> PING fsf.org (209.51.188.174) 56(84) bytes of data.
> 0.0181: pasta: epoll event on /dev/net/tun device 16 (events: 0x00000001)
> 0.0181: pasta: epoll event on /dev/net/tun device 16 (events: 0x00000001)
> 0.0182: tap: protocol 1, 192.168.100.157 -> 209.51.188.174 (1 packet)

-- 
Stefano