[pkg-apparmor] Bug#881460: apparmor-profiles: dhclient set to enforce prevents getting an IPv4 with DHCP

Sun Nov 12 02:35:13 UTC 2017

Package: apparmor-profiles
Version: 2.11.1-3
Severity: critical
Justification: breaks unrelated software

Hello,

I've started using apparmor very recently, and when I rebooted to
activate the kernel part, I didn't notice the issue below.. but a couple
reboots afterwards I couldn't obtain a DHCP address anymore for wired
and wifi interfaces.

>From what I could see, when dhclient6 gets called by network-manager,
this program gets denied a bunch of operations which makes it not do
what it's supposed to and just exit.

The weird part that I don't understand yet is that I don't think I've
installed or upgraded anything else since I enabled apparmor (so why
didn't I see this in a more consistent manner?).

In the syslog I found the following log lines that are relevant:

Nov 11 16:53:14 boohn kernel: [   15.622076] audit: type=1400 audit(1510437193.949:5): apparmor="STATUS" operation="profile_load" profile="unconfined" name="dhclient" pid=620 comm="apparmor_parser"
Nov 11 16:53:20 boohn NetworkManager[678]: <info>  [1510437200.9563] dhcp-init: Using DHCP client 'dhclient'
Nov 11 16:53:24 boohn NetworkManager[678]: <info>  [1510437204.1739] dhcp4 (eth0): dhclient started with pid 1184
Nov 11 16:53:24 boohn dhclient[1185]: execve (/usr/lib/NetworkManager/nm-dhcp-helper, ...): Permission denied
Nov 11 16:53:24 boohn kernel: [   25.862578] audit: type=1400 audit(1510437204.189:74): apparmor="DENIED" operation="exec" profile="dhclient" name="/usr/lib/NetworkManager/nm-dhcp-helper" pid=1185 comm="dhclient" requested_mask="x" denied_mask="x" fsuid=0 ouid=0
Nov 11 16:53:24 boohn dhclient[1184]: DHCPREQUEST of 192.168.2.243 on eth0 to 255.255.255.255 port 67
Nov 11 16:53:24 boohn dhclient[1184]: DHCPNAK from 192.168.2.1
Nov 11 16:53:24 boohn dhclient[1186]: execve (/usr/lib/NetworkManager/nm-dhcp-helper, ...): Permission denied
Nov 11 16:53:24 boohn kernel: [   25.887214] audit: type=1400 audit(1510437204.214:75): apparmor="DENIED" operation="exec" profile="dhclient" name="/usr/lib/NetworkManager/nm-dhcp-helper" pid=1186 comm="dhclient" requested_mask="x" denied_mask="x" fsuid=0 ouid=0
Nov 11 16:53:24 boohn kernel: [   25.887967] audit: type=1400 audit(1510437204.215:76): apparmor="DENIED" operation="exec" profile="dhclient" name="/usr/lib/NetworkManager/nm-dhcp-helper" pid=1187 comm="dhclient" requested_mask="x" denied_mask="x" fsuid=0 ouid=0
Nov 11 16:53:24 boohn dhclient[1187]: execve (/usr/lib/NetworkManager/nm-dhcp-helper, ...): Permission denied
Nov 11 16:53:24 boohn dhclient[1184]: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 3
Nov 11 16:53:24 boohn dhclient[1184]: DHCPREQUEST of 192.168.2.233 on eth0 to 255.255.255.255 port 67
Nov 11 16:53:24 boohn dhclient[1184]: DHCPOFFER of 192.168.2.233 from 192.168.2.1
Nov 11 16:53:24 boohn dhclient[1184]: DHCPACK of 192.168.2.233 from 192.168.2.1
Nov 11 16:53:24 boohn dhclient[1188]: execve (/usr/lib/NetworkManager/nm-dhcp-helper, ...): Permission denied
Nov 11 16:53:24 boohn kernel: [   25.894073] audit: type=1400 audit(1510437204.221:77): apparmor="DENIED" operation="exec" profile="dhclient" name="/usr/lib/NetworkManager/nm-dhcp-helper" pid=1188 comm="dhclient" requested_mask="x" denied_mask="x" fsuid=0 ouid=0
Nov 11 16:53:24 boohn dhclient[1184]: bound to 192.168.2.233 -- renewal in 37728 seconds.
Nov 11 16:53:26 boohn NetworkManager[678]: <info>  [1510437206.3351] dhcp6 (eth0): dhclient started with pid 1189
Nov 11 16:53:26 boohn kernel: [   28.012088] audit: type=1400 audit(1510437206.339:78): apparmor="DENIED" operation="open" profile="dhclient" name="/var/lib/NetworkManager/dhclient6-eth0.conf" pid=1189 comm="dhclient" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Nov 11 16:53:26 boohn kernel: [   28.012098] audit: type=1400 audit(1510437206.339:79): apparmor="DENIED" operation="open" profile="dhclient" name="/var/lib/NetworkManager/dhclient6-b63c69a8-9bf3-4eef-9610-09eee2527a06-eth0.lease" pid=1189 comm="dhclient" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Nov 11 16:53:26 boohn kernel: [   28.012104] audit: type=1400 audit(1510437206.339:80): apparmor="DENIED" operation="open" profile="dhclient" name="/var/lib/NetworkManager/dhclient6-b63c69a8-9bf3-4eef-9610-09eee2527a06-eth0.lease" pid=1189 comm="dhclient" requested_mask="wc" denied_mask="wc" fsuid=0 ouid=0
Nov 11 16:53:26 boohn dhclient[1189]: can't create /var/lib/NetworkManager/dhclient6-b63c69a8-9bf3-4eef-9610-09eee2527a06-eth0.lease: Permission denied
Nov 11 16:53:26 boohn dhclient[1190]: execve (/usr/lib/NetworkManager/nm-dhcp-helper, ...): Permission denied
Nov 11 16:53:26 boohn dhclient[1189]: Created duid "\000\001\000\001!\232-\326\360\336\361+\253L".
Nov 11 16:53:26 boohn dhclient[1189]: can't create /var/lib/NetworkManager/dhclient6-b63c69a8-9bf3-4eef-9610-09eee2527a06-eth0.lease: Permission denied
Nov 11 16:53:26 boohn dhclient[1189]: Can't create /run/dhclient6-eth0.pid: Permission denied
Nov 11 16:53:26 boohn kernel: [   28.012575] audit: type=1400 audit(1510437206.339:81): apparmor="DENIED" operation="exec" profile="dhclient" name="/usr/lib/NetworkManager/nm-dhcp-helper" pid=1190 comm="dhclient" requested_mask="x" denied_mask="x" fsuid=0 ouid=0
Nov 11 16:53:26 boohn kernel: [   28.013580] audit: type=1400 audit(1510437206.340:82): apparmor="DENIED" operation="open" profile="dhclient" name="/var/lib/NetworkManager/dhclient6-b63c69a8-9bf3-4eef-9610-09eee2527a06-eth0.lease" pid=1189 comm="dhclient" requested_mask="wc" denied_mask="wc" fsuid=0 ouid=0
Nov 11 16:53:26 boohn kernel: [   28.013642] audit: type=1400 audit(1510437206.341:83): apparmor="DENIED" operation="mknod" profile="dhclient" name="/run/dhclient6-eth0.pid" pid=1189 comm="dhclient" requested_mask="c" denied_mask="c" fsuid=0 ouid=0
Nov 11 16:53:26 boohn dhclient[1189]: XMT: Solicit on eth0, interval 1020ms.
Nov 11 16:53:26 boohn dhclient[1189]: RCV: Advertise message on eth0 from fe80::223:69ff:febf:3d6e.
Nov 11 16:53:27 boohn dhclient[1189]: XMT: Solicit on eth0, interval 2100ms.
Nov 11 16:53:27 boohn dhclient[1189]: RCV: Advertise message on eth0 from fe80::223:69ff:febf:3d6e.
Nov 11 16:53:29 boohn NetworkManager[678]: <info>  [1510437209.3970] dhcp4 (wlan0): dhclient started with pid 1214
Nov 11 16:53:29 boohn dhclient[1215]: execve (/usr/lib/NetworkManager/nm-dhcp-helper, ...): Permission denied
Nov 11 16:53:29 boohn kernel: [   31.075386] audit: type=1400 audit(1510437209.402:84): apparmor="DENIED" operation="exec" profile="dhclient" name="/usr/lib/NetworkManager/nm-dhcp-helper" pid=1215 comm="dhclient" requested_mask="x" denied_mask="x" fsuid=0 ouid=0
Nov 11 16:53:29 boohn dhclient[1214]: DHCPREQUEST of 192.168.2.215 on wlan0 to 255.255.255.255 port 67
Nov 11 16:53:29 boohn dhclient[1214]: DHCPACK of 192.168.2.215 from 192.168.2.1
Nov 11 16:53:29 boohn dhclient[1216]: execve (/usr/lib/NetworkManager/nm-dhcp-helper, ...): Permission denied
Nov 11 16:53:29 boohn kernel: [   31.110227] audit: type=1400 audit(1510437209.437:85): apparmor="DENIED" operation="exec" profile="dhclient" name="/usr/lib/NetworkManager/nm-dhcp-helper" pid=1216 comm="dhclient" requested_mask="x" denied_mask="x" fsuid=0 ouid=0
Nov 11 16:53:29 boohn dhclient[1214]: bound to 192.168.2.215 -- renewal in 38417 seconds.
Nov 11 16:53:29 boohn dhclient[1189]: XMT: Solicit on eth0, interval 4260ms.
Nov 11 16:53:29 boohn dhclient[1189]: RCV: Advertise message on eth0 from fe80::223:69ff:febf:3d6e.
Nov 11 16:53:31 boohn NetworkManager[678]: <info>  [1510437211.4239] dhcp6 (wlan0): dhclient started with pid 1221
Nov 11 16:53:31 boohn dhclient[1221]: can't create /var/lib/NetworkManager/dhclient6-fabf53ca-ae6c-42c6-b9e8-51bce175d379-wlan0.lease: Permission denied
Nov 11 16:53:31 boohn dhclient[1222]: execve (/usr/lib/NetworkManager/nm-dhcp-helper, ...): Permission denied
Nov 11 16:53:31 boohn dhclient[1221]: Created duid "\000\001\000\001!\232-\333\000$\327iQ\244".
Nov 11 16:53:31 boohn dhclient[1221]: can't create /var/lib/NetworkManager/dhclient6-fabf53ca-ae6c-42c6-b9e8-51bce175d379-wlan0.lease: Permission denied
Nov 11 16:53:31 boohn dhclient[1221]: Can't create /run/dhclient6-wlan0.pid: Permission denied
Nov 11 16:53:31 boohn kernel: [   33.100723] audit: type=1400 audit(1510437211.428:86): apparmor="DENIED" operation="open" profile="dhclient" name="/var/lib/NetworkManager/dhclient6-wlan0.conf" pid=1221 comm="dhclient" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Nov 11 16:53:31 boohn kernel: [   33.100730] audit: type=1400 audit(1510437211.428:87): apparmor="DENIED" operation="open" profile="dhclient" name="/var/lib/NetworkManager/dhclient6-fabf53ca-ae6c-42c6-b9e8-51bce175d379-wlan0.lease" pid=1221 comm="dhclient" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Nov 11 16:53:31 boohn kernel: [   33.100734] audit: type=1400 audit(1510437211.428:88): apparmor="DENIED" operation="open" profile="dhclient" name="/var/lib/NetworkManager/dhclient6-fabf53ca-ae6c-42c6-b9e8-51bce175d379-wlan0.lease" pid=1221 comm="dhclient" requested_mask="wc" denied_mask="wc" fsuid=0 ouid=0
Nov 11 16:53:31 boohn kernel: [   33.101133] audit: type=1400 audit(1510437211.428:89): apparmor="DENIED" operation="exec" profile="dhclient" name="/usr/lib/NetworkManager/nm-dhcp-helper" pid=1222 comm="dhclient" requested_mask="x" denied_mask="x" fsuid=0 ouid=0
Nov 11 16:53:31 boohn kernel: [   33.102095] audit: type=1400 audit(1510437211.429:90): apparmor="DENIED" operation="open" profile="dhclient" name="/var/lib/NetworkManager/dhclient6-fabf53ca-ae6c-42c6-b9e8-51bce175d379-wlan0.lease" pid=1221 comm="dhclient" requested_mask="wc" denied_mask="wc" fsuid=0 ouid=0
Nov 11 16:53:31 boohn kernel: [   33.102155] audit: type=1400 audit(1510437211.429:91): apparmor="DENIED" operation="mknod" profile="dhclient" name="/run/dhclient6-wlan0.pid" pid=1221 comm="dhclient" requested_mask="c" denied_mask="c" fsuid=0 ouid=0
Nov 11 16:54:09 boohn NetworkManager[678]: <warn>  [1510437249.3316] dhcp4 (eth0): request timed out
Nov 11 16:54:09 boohn NetworkManager[678]: <info>  [1510437249.3317] dhcp4 (eth0): state changed unknown -> timeout
Nov 11 16:54:09 boohn NetworkManager[678]: <info>  [1510437249.3641] dhcp4 (eth0): canceled DHCP transaction, DHCP client pid 1184
Nov 11 16:54:09 boohn NetworkManager[678]: <info>  [1510437249.3642] dhcp4 (eth0): state changed timeout -> done
Nov 11 16:54:11 boohn NetworkManager[678]: <warn>  [1510437251.3298] dhcp6 (eth0): request timed out
Nov 11 16:54:11 boohn NetworkManager[678]: <info>  [1510437251.3299] dhcp6 (eth0): state changed unknown -> timeout
Nov 11 16:54:11 boohn NetworkManager[678]: <info>  [1510437251.3308] dhcp6 (eth0): canceled DHCP transaction, DHCP client pid 1189
Nov 11 16:54:11 boohn NetworkManager[678]: <info>  [1510437251.3308] dhcp6 (eth0): state changed timeout -> done
Nov 11 16:54:11 boohn NetworkManager[678]: <info>  [1510437251.3317] device (eth0): state change: ip-config -> ip-check (reason 'none', internal state 'managed')
Nov 11 16:54:11 boohn NetworkManager[678]: <info>  [1510437251.3327] device (eth0): state change: ip-check -> secondaries (reason 'none', internal state 'managed')
Nov 11 16:54:11 boohn NetworkManager[678]: <info>  [1510437251.3335] device (eth0): state change: secondaries -> activated (reason 'none', internal state 'managed')
Nov 11 16:54:11 boohn NetworkManager[678]: <info>  [1510437251.3561] device (eth0): Activation: successful, device activated.
Nov 11 16:54:11 boohn dbus-daemon[672]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service' requested by
 ':1.7' (uid=0 pid=678 comm="/usr/sbin/NetworkManager --no-daemon ")
Nov 11 16:54:11 boohn systemd[1]: Starting Network Manager Script Dispatcher Service...
Nov 11 16:54:11 boohn dbus-daemon[672]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Nov 11 16:54:11 boohn systemd[1]: Started Network Manager Script Dispatcher Service.
Nov 11 16:54:11 boohn nm-dispatcher: req:1 'up' [eth0]: new request (2 scripts)
Nov 11 16:54:11 boohn nm-dispatcher: req:1 'up' [eth0]: start running ordered scripts...
Nov 11 16:54:14 boohn NetworkManager[678]: <warn>  [1510437254.3307] dhcp4 (wlan0): request timed out
Nov 11 16:54:14 boohn NetworkManager[678]: <info>  [1510437254.3308] dhcp4 (wlan0): state changed unknown -> timeout
Nov 11 16:54:14 boohn NetworkManager[678]: <info>  [1510437254.3472] dhcp4 (wlan0): canceled DHCP transaction, DHCP client pid 1214
Nov 11 16:54:14 boohn NetworkManager[678]: <info>  [1510437254.3472] dhcp4 (wlan0): state changed timeout -> done
Nov 11 16:54:16 boohn NetworkManager[678]: <warn>  [1510437256.3290] dhcp6 (wlan0): request timed out
Nov 11 16:54:16 boohn NetworkManager[678]: <info>  [1510437256.3291] dhcp6 (wlan0): state changed unknown -> timeout
Nov 11 16:54:16 boohn NetworkManager[678]: <info>  [1510437256.3299] dhcp6 (wlan0): canceled DHCP transaction, DHCP client pid 1221
Nov 11 16:54:16 boohn NetworkManager[678]: <info>  [1510437256.3300] dhcp6 (wlan0): state changed timeout -> done
Nov 11 16:54:16 boohn NetworkManager[678]: <info>  [1510437256.3308] device (wlan0): state change: ip-config -> ip-check (reason 'none', internal state 'managed')
Nov 11 16:54:16 boohn NetworkManager[678]: <info>  [1510437256.3317] device (wlan0): state change: ip-check -> secondaries (reason 'none', internal state 'managed')
Nov 11 16:54:16 boohn NetworkManager[678]: <info>  [1510437256.3323] device (wlan0): state change: secondaries -> activated (reason 'none', internal state 'managed')
Nov 11 16:54:16 boohn NetworkManager[678]: <info>  [1510437256.3327] manager: NetworkManager state is now CONNECTED_LOCAL

according to the logs I did send a dhcp broadcast and got a response,
network-manager even was convinced that the interfaces were up and
configured, but according to "ip addr" neither eth0 nor wlan0 had an IP.

there's a lot of errors in the log lines that are about things for
dhclient6. I don't have IPv6 so I'm not sure that it's relevant to the
fact that I wasn't able to get an IP assigned to any interface.

To fix this, I used "aa-complain sbin.dhclient", then rebooted (mostly
cause I don't know how to make sure the new profile is being used or
not) and then I was able to connect to the network again and in the
logs, opreations started showing with ACCEPT instead of DENIED.
I'm still a bit mystified by this change.. I would have expected
aa-complain to make the profile report the same denials but them not
blocking anything.

fwiw, I've kept the log file around so if you need more info from there
I can dig further.

-- System Information:
Debian Release: buster/sid
  APT prefers unstable
  APT policy: (500, 'unstable')
Architecture: amd64 (x86_64)

Kernel: Linux 4.13.0-1-amd64 (SMP w/4 CPU cores)
Locale: LANG=en_CA.utf8, LC_CTYPE=en_CA.utf8 (charmap=UTF-8) (ignored: LC_ALL set to en_CA.utf8), LANGUAGE=en_CA.utf8 (charmap=UTF-8) (ignored: LC_ALL set to en_CA.utf8)
Shell: /bin/sh linked to /bin/dash
Init: systemd (via /run/systemd/system)

Versions of packages apparmor-profiles depends on:
ii  apparmor  2.11.1-3

apparmor-profiles recommends no packages.

apparmor-profiles suggests no packages.

-- no debconf information