Last nights isc-dhcp-server update fails to start

Bug #1171838 reported by Charles Peters II
16
This bug affects 3 people
Affects Status Importance Assigned to Milestone
isc-dhcp (Ubuntu)
Fix Released
High
Unassigned
Quantal
Fix Released
High
Stéphane Graber

Bug Description

== Rational ==
The recent isc-dhcp SRU to quantal introduced a patch that fixes cases where checksum offloading would cause the checksum to be empty by having dhcpd re-calculate the checksum in those case.

This requires dhcpd to use raw sockets, unfortunately I forgot to allow those in the apparmor profile.

I've had 3 report so far of people who got a broken dhcpd post-upgrade and I suspect the number to be far higher.

The fix simply copies the apparmor profile as we have it in raring which allows the extra socket type.

== Test case ==
1) Install dhcpd on a machine that does checksum offloading (virtual machine with virtio for example) or uses infiniband
2) Check that dhcpd starts

== Regression potential ==
This is a direct copy of the apparmor profile from raring. The dmesg entry below quite clearly matches the socket type, so I don't expect any regression to happen.

--- Original bug report ---
This is Ubuntu 12.10

Start-Date: 2013-04-22 20:48:32
Commandline: apt-get --assume-yes dist-upgrade
Upgrade: isc-dhcp-client:i386 (4.2.4-1ubuntu10.1, 4.2.4-1ubuntu10.2), isc-dhcp-common:i386 (4.2.4-1ubuntu10.1, 4.2.4-1ubuntu10.2), isc-dhcp-server:i386 (4.2.4-1ubuntu10.1, 4.2.4-1ubuntu10.2)
End-Date: 2013-04-22 20:49:28

I forced a downgrade to the previous packages isc-dhcp-client_4.2.4-1ubuntu10.1_i386.deb
isc-dhcp-common_4.2.4-1ubuntu10.1_i386.deb isc-dhcp-server_4.2.4-1ubuntu10.1_i386.deb and it is working now.

Here a few of the log entries from when it was working to when it stopped working:

Apr 22 20:27:57 io dhcpd: DHCPACK to 192.168.2.98 (00:1f:d0:d0:ed:50) via eth1
Apr 22 20:38:00 io dhcpd: DHCPINFORM from 192.168.2.98 via eth1
Apr 22 20:38:00 io dhcpd: DHCPACK to 192.168.2.98 (00:1f:d0:d0:ed:50) via eth1
Apr 22 20:48:02 io dhcpd: DHCPINFORM from 192.168.2.98 via eth1
Apr 22 20:48:02 io dhcpd: DHCPACK to 192.168.2.98 (00:1f:d0:d0:ed:50) via eth1
Apr 22 20:49:21 io dhcpd: Wrote 0 deleted host decls to leases file.
Apr 22 20:49:21 io dhcpd: Wrote 0 new dynamic host decls to leases file.
Apr 22 20:49:21 io dhcpd: Wrote 31 leases to leases file.
Apr 22 20:49:21 io dhcpd: Open a socket for LPF: Permission denied
Apr 22 20:49:21 io kernel: [168459.938698] type=1400 audit(1366678161.188:42): apparmor="DENIED" operation="create" parent=1 profile="/usr/sbin/dhcpd" pid=2443 comm="dhcpd" family="packet" sock_type="raw" protocol=768
Apr 22 20:49:21 io dhcpd: Wrote 0 deleted host decls to leases file.
Apr 22 20:49:21 io dhcpd: Wrote 0 new dynamic host decls to leases file.
Apr 22 20:49:21 io dhcpd: Wrote 31 leases to leases file.
Apr 22 20:49:21 io dhcpd: Open a socket for LPF: Permission denied
Apr 22 20:49:21 io kernel: [168460.091513] type=1400 audit(1366678161.340:43): apparmor="DENIED" operation="create" parent=1 profile="/usr/sbin/dhcpd" pid=2482 comm="dhcpd" family="packet" sock_type="raw" protocol=768
Apr 22 20:49:21 io dhcpd: Wrote 0 deleted host decls to leases file.
Apr 22 20:49:21 io dhcpd: Wrote 0 new dynamic host decls to leases file.
Apr 22 20:49:21 io dhcpd: Wrote 31 leases to leases file.
Apr 22 20:49:21 io dhcpd: Open a socket for LPF: Permission denied
Apr 22 20:49:21 io kernel: [168460.404076] type=1400 audit(1366678161.656:44): apparmor="DENIED" operation="create" parent=1 profile="/usr/sbin/dhcpd" pid=2491 comm="dhcpd" family="packet" sock_type="raw" protocol=768
Apr 22 20:49:21 io dhcpd: Wrote 0 deleted host decls to leases file.
Apr 22 20:49:21 io dhcpd: Wrote 0 new dynamic host decls to leases file.
Apr 22 20:49:21 io dhcpd: Wrote 31 leases to leases file.
Apr 22 20:49:21 io dhcpd: Open a socket for LPF: Permission denied
Apr 22 20:49:21 io kernel: [168460.487047] type=1400 audit(1366678161.736:45): apparmor="DENIED" operation="create" parent=1 profile="/usr/sbin/dhcpd" pid=2498 comm="dhcpd" family="packet" sock_type="raw" protocol=768
Apr 22 20:49:21 io dhcpd: Wrote 0 deleted host decls to leases file.
Apr 22 20:49:21 io dhcpd: Wrote 0 new dynamic host decls to leases file.
Apr 22 20:49:21 io dhcpd: Wrote 31 leases to leases file.
Apr 22 20:49:21 io dhcpd: Open a socket for LPF: Permission denied

pr 23 07:14:39 io dhcpd: Wrote 31 leases to leases file.
Apr 23 07:14:40 io dhcpd: Open a socket for LPF: Permission denied
Apr 23 07:14:40 io kernel: [ 49.077715] type=1400 audit(1366715680.165:46): apparmor="DENIED" operation="create" parent=1 profile="/usr/sbin/dhcpd" pid=1817 comm="dhcpd" family="packet" sock_type="raw" protocol=768
Apr 23 07:14:40 io dhcpd: Wrote 0 deleted host decls to leases file.
Apr 23 07:14:40 io dhcpd: Wrote 0 new dynamic host decls to leases file.
Apr 23 07:14:40 io dhcpd: Wrote 31 leases to leases file.
Apr 23 07:14:40 io dhcpd: Open a socket for LPF: Permission denied
Apr 23 07:14:40 io kernel: [ 49.248752] type=1400 audit(1366715680.337:47): apparmor="DENIED" operation="create" parent=1 profile="/usr/sbin/dhcpd" pid=1892 comm="dhcpd" family="packet" sock_type="raw" protocol=768
Apr 23 07:14:40 io dhcpd: Wrote 0 deleted host decls to leases file.
Apr 23 07:14:40 io dhcpd: Wrote 0 new dynamic host decls to leases file.
Apr 23 07:14:40 io dhcpd: Wrote 31 leases to leases file.
Apr 23 07:14:40 io dhcpd: Open a socket for LPF: Permission denied
Apr 23 07:14:40 io kernel: [ 49.509316] type=1400 audit(1366715680.597:48): apparmor="DENIED" operation="create" parent=1 profile="/usr/sbin/dhcpd" pid=2101 comm="dhcpd" family="packet" sock_type="raw" protocol=768
Apr 23 07:14:40 io dhcpd: Wrote 0 deleted host decls to leases file.
Apr 23 07:14:40 io dhcpd: Wrote 0 new dynamic host decls to leases file.
Apr 23 07:14:40 io dhcpd: Wrote 31 leases to leases file.
Apr 23 07:14:41 io dhcpd: Open a socket for LPF: Permission denied
Apr 23 07:14:41 io kernel: [ 49.956465] type=1400 audit(1366715681.045:49): apparmor="DENIED" operation="create" parent=1 profile="/usr/sbin/dhcpd" pid=2119 comm="dhcpd" family="packet" sock_type="raw" protocol=768
Apr 23 07:14:41 io dhcpd: Wrote 0 deleted host decls to leases file.
Apr 23 07:14:41 io dhcpd: Wrote 0 new dynamic host decls to leases file.
Apr 23 07:14:41 io dhcpd: Wrote 31 leases to leases file.
Apr 23 07:14:41 io dhcpd: Open a socket for LPF: Permission denied
Apr 23 07:14:41 io kernel: [ 50.147287] type=1400 audit(1366715681.237:50): apparmor="DENIED" operation="create" parent=1 profile="/usr/sbin/dhcpd" pid=2139 comm="dhcpd" family="packet" sock_type="raw" protocol=768
Apr 23 07:14:41 io dhcpd: Wrote 0 deleted host decls to leases file.
Apr 23 07:14:41 io dhcpd: Wrote 0 new dynamic host decls to leases file.
Apr 23 07:14:41 io dhcpd: Wrote 31 leases to leases file.
Apr 23 07:14:41 io dhcpd: Open a socket for LPF: Permission denied
Apr 23 07:14:41 io kernel: [ 50.332243] type=1400 audit(1366715681.421:51): apparmor="DENIED" operation="create" parent=1 profile="/usr/sbin/dhcpd" pid=2154 comm="dhcpd" family="packet" sock_type="raw" protocol=768

Changed in isc-dhcp (Ubuntu):
status: New → Triaged
importance: Undecided → High
status: Triaged → Fix Released
Changed in isc-dhcp (Ubuntu Quantal):
status: New → Triaged
importance: Undecided → High
assignee: nobody → Stéphane Graber (stgraber)
description: updated
Changed in isc-dhcp (Ubuntu Quantal):
status: Triaged → In Progress
Revision history for this message
Stéphane Graber (stgraber) wrote :

For anyone affected by this bug and who can't wait for the bugfix to land, you can simply edit /etc/apparmor.d/usr.sbin.dhcpd and apply the following diff, then do "sudo /etc/init.d/apparmor reload".

diff -Nru isc-dhcp-4.2.4/debian/apparmor-profile.dhcpd isc-dhcp-4.2.4/debian/apparmor-profile.dhcpd
--- isc-dhcp-4.2.4/debian/apparmor-profile.dhcpd 2012-10-16 21:25:47.000000000 +0200
+++ isc-dhcp-4.2.4/debian/apparmor-profile.dhcpd 2013-04-23 17:16:49.000000000 +0200
@@ -16,6 +16,8 @@

   network inet raw,
   network packet packet,
+ network packet raw,
+
   @{PROC}/[0-9]*/net/dev r,
   @{PROC}/[0-9]*/net/{dev,if_inet6} r,

Revision history for this message
Steve Langasek (vorlon) wrote : Please test proposed package

Hello cp, or anyone else affected,

Accepted isc-dhcp into quantal-proposed. The package will build now and be available at http://launchpad.net/ubuntu/+source/isc-dhcp/4.2.4-1ubuntu10.3 in a few hours, and then in the -proposed repository.

Please help us by testing this new package. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation how to enable and use -proposed. Your feedback will aid us getting this update out to other Ubuntu users.

If this package fixes the bug for you, please add a comment to this bug, mentioning the version of the package you tested, and change the tag from verification-needed to verification-done. If it does not fix the bug for you, please add a comment stating that, and change the tag to verification-failed. In either case, details of your testing will help us make a better decision.

Further information regarding the verification process can be found at https://wiki.ubuntu.com/QATeam/PerformingSRUVerification . Thank you in advance!

Changed in isc-dhcp (Ubuntu Quantal):
status: In Progress → Fix Committed
tags: added: verification-needed
Revision history for this message
Scott Kitterman (kitterman) wrote : Re: [Bug 1171838] Re: Last nights isc-dhcp-server update fails to start

The fix was independently verified by two people. What should we have done differently to catch this during verification?

Revision history for this message
Stéphane Graber (stgraber) wrote :

Well, I should have noticed it when reviewing the patch as the patch quite clearly uses raw sockets...

To catch this in testing, we'd have required a larger hardware pool to hit both machines with checksum offloading and without, also check that the test results where from machine where apparmor was turned on.

Revision history for this message
Charles Peters II (cp) wrote :

Enabled proposed and apt-get install isc-dhcp-server isc-dhcp-client and it works.

# ps auwx|grep dhcp
dhcpd 9201 0.0 0.1 7792 4892 ? Ss 20:37 0:00 dhcpd -user dhcpd -group dhcpd -f -q -4 -pf /run/dhcp-server/dhcpd.pid -cf /etc/ltsp/dhcpd.conf

Thanks!

Revision history for this message
Scott Kitterman (kitterman) wrote :

cp: Did you have a problem with the first update?

Revision history for this message
Charles Peters II (cp) wrote :

kitterman: Yes 4.2.4-1ubuntu10.2 failed to start. I reported this bug.

4.2.4-1ubuntu10.3 is currently working fine.

Revision history for this message
Scott Kitterman (kitterman) wrote :

Excellent. Based on that and that this is a regression in updates, I'll release the package early.

tags: added: verification-done
removed: verification-needed
Revision history for this message
Scott Kitterman (kitterman) wrote : Update Released

The verification of this Stable Release Update has completed successfully and the package has now been released to -updates. Subsequently, the Ubuntu Stable Release Updates Team is being unsubscribed and will not receive messages about this bug report. In the event that you encounter a regression using the package from -updates please report a new bug using ubuntu-bug and tag the bug report regression-update so we can easily find any regresssions.

Revision history for this message
Launchpad Janitor (janitor) wrote :

This bug was fixed in the package isc-dhcp - 4.2.4-1ubuntu10.3

---------------
isc-dhcp (4.2.4-1ubuntu10.3) quantal-proposed; urgency=low

  * Allow "network packet raw" in the apparmor profile for dhcpd.
    This fixes dhcpd failing to start when used on InfiniBand and on setups
    that do checksum offloading (fixes a bug introduced by the previous upload)
    (LP: #1171838)
 -- Stephane Graber <email address hidden> Tue, 23 Apr 2013 17:16:56 +0200

Changed in isc-dhcp (Ubuntu Quantal):
status: Fix Committed → Fix Released
Revision history for this message
Tom Northeast (tom-northeast) wrote :

I'm running 4.2.4-1ubuntu10.3 and still experiencing the error. Adding 'network packet raw' to usr.sbin.dhcpd fixed the issue for now.

have I somehow skipped the apparmor config during the update?

Revision history for this message
Robert E Blair (reblair) wrote :

I have had this issue off and on for a couple of weeks. After much tearing of hair and gnashing of teeth I believe I fixed it. In the upstart configuration for isc-dhcp-server there is no stanza of the form:
/lib/init/apparmor-profile-load usr.sbin.dhcpd
I don't know about systems running NM but if you have a dhcp server running likely you don't want NM taking your connections up and down (I remob\ved NM from this system and statically configure the network) but the apparmor profile likely needs to be there in cases where the network is statically configured. The apparmor configuration likely is loaded too late on these systems and this causes much grief.

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.