apparmor errors on startup

Hi Matt, could you please attach your /etc/apparmor.d/usr.sbin.cupsd file please?

Sure, though it's the default one provided by the cups package.

Matt - I'm not seeing any similar audit messages in my log with the default Apparmor configuration. Have you installed any third party printer drivers at all by any chance?

Thanks

On Tue, Aug 05, 2008 at 06:53:37PM -0000, Chris Coulson wrote:
> Matt - I'm not seeing any similar audit messages in my log with the
> default Apparmor configuration. Have you installed any third party
> printer drivers at all by any chance?

I have a couple of third-party PPDs, but nothing which uses a custom driver.
I'm not the only one seeing this, either; I noticed in an unrelated bug that
Martin Pitt has the same thing in his dmesg:

http://launchpadlibrarian.net/16557148/CurrentDmesg.txt

--
 - mdz

Indeed, the new apparmor in intrepid has some refined network rules, so we need to adapt the profile.

This does not happen for me any more with the latest intrepid kernel/apparmor. Please reopen if it still happens for you.

I only get these now:

[170986.269229] type=1505 audit(1220449138.810:6): operation="profile_replace" name="/usr/lib/cups/backend/cups-pdf" name2="default" pid=5738
[170986.269510] type=1505 audit(1220449138.810:7): operation="profile_replace" name="/usr/sbin/cupsd" name2="default" pid=5738

I was searching for what this stuff in my dmesg meant and stumbled across this bug report..

Here is the end of a dmesg just after bootup:

[ 141.127059] type=1503 audit(1224108907.545:5): operation="inode_permission" requested_mask="r::" denied_mask="r::" fsuid=7 name="/proc/6409/net/" pid=6409 profile="/usr/sbin/cupsd"
[ 142.395682] type=1503 audit(1224108908.813:6): operation="inode_permission" requested_mask="r::" denied_mask="r::" fsuid=7 name="/proc/6419/net/" pid=6419 profile="/usr/sbin/cupsd"
[ 142.398258] type=1503 audit(1224108908.817:7): operation="socket_create" family="ax25" sock_type="dgram" protocol=0 pid=6419 profile="/usr/sbin/cupsd"
[ 142.398280] type=1503 audit(1224108908.817:8): operation="socket_create" family="netrom" sock_type="seqpacket" protocol=0 pid=6419 profile="/usr/sbin/cupsd"
[ 142.398299] type=1503 audit(1224108908.817:9): operation="socket_create" family="rose" sock_type="dgram" protocol=0 pid=6419 profile="/usr/sbin/cupsd"
[ 142.398318] type=1503 audit(1224108908.817:10): operation="socket_create" family="ipx" sock_type="dgram" protocol=0 pid=6419 profile="/usr/sbin/cupsd"
[ 142.398338] type=1503 audit(1224108908.817:11): operation="socket_create" family="appletalk" sock_type="dgram" protocol=0 pid=6419 profile="/usr/sbin/cupsd"
[ 142.398357] type=1503 audit(1224108908.817:12): operation="socket_create" family="econet" sock_type="dgram" protocol=0 pid=6419 profile="/usr/sbin/cupsd"
[ 142.398376] type=1503 audit(1224108908.817:13): operation="socket_create" family="ash" sock_type="dgram" protocol=0 pid=6419 profile="/usr/sbin/cupsd"
[ 142.398394] type=1503 audit(1224108908.817:14): operation="socket_create" family="x25" sock_type="seqpacket" protocol=0 pid=6419 profile="/usr/sbin/cupsd"
[ 231.705065] __ratelimit: 3 callbacks suppressed
[ 231.705081] ACPI: EC: missing confirmations, switch off interrupt mode.
[ 232.208190] ACPI Exception (evregion-0419): AE_TIME, Returned by Handler for [EmbeddedControl] [20080609]
[ 232.208227] ACPI Error (psparse-0530): Method parse/execution failed [\_SB_.PCI0.LPCB.EC0_.BPOL] (Node f741b9a8), AE_TIME
[ 232.208333] ACPI Error (psparse-0530): Method parse/execution failed [\_TZ_.TZ00._TMP] (Node f7415240), AE_TIME

Looks like it may be related

I can confirm that this appears to have regressed. From my /var/log/audit/audit.log:

type=APPARMOR_DENIED msg=audit(1224193295.002:19): operation="inode_permission" requested_mask="r::" denied_mask="r::" fsuid=7 name="/proc/8339/net/" pid=8339 profile="/usr/sbin/cupsd"
type=APPARMOR_DENIED msg=audit(1224193295.882:20): operation="inode_permission" requested_mask="r::" denied_mask="r::" fsuid=7 name="/proc/8343/net/" pid=8343 profile="/usr/sbin/cupsd"
type=APPARMOR_DENIED msg=audit(1224193295.882:21): operation="socket_create" family="ax25" sock_type="dgram" protocol=0 pid=8343 profile="/usr/sbin/cupsd"
type=APPARMOR_DENIED msg=audit(1224193295.882:22): operation="socket_create" family="netrom" sock_type="seqpacket" protocol=0 pid=8343 profile="/usr/sbin/cupsd"
type=APPARMOR_DENIED msg=audit(1224193295.882:23): operation="socket_create" family="rose" sock_type="dgram" protocol=0 pid=8343 profile="/usr/sbin/cupsd"
type=APPARMOR_DENIED msg=audit(1224193295.882:24): operation="socket_create" family="ipx" sock_type="dgram" protocol=0 pid=8343 profile="/usr/sbin/cupsd"
type=APPARMOR_DENIED msg=audit(1224193295.882:25): operation="socket_create" family="appletalk" sock_type="dgram" protocol=0 pid=8343 profile="/usr/sbin/cupsd"
type=APPARMOR_DENIED msg=audit(1224193295.882:26): operation="socket_create" family="econet" sock_type="dgram" protocol=0 pid=8343 profile="/usr/sbin/cupsd"
type=APPARMOR_DENIED msg=audit(1224193295.882:27): operation="socket_create" family="ash" sock_type="dgram" protocol=0 pid=8343 profile="/usr/sbin/cupsd"
type=APPARMOR_DENIED msg=audit(1224193295.882:28): operation="socket_create" family="x25" sock_type="seqpacket" protocol=0 pid=8343 profile="/usr/sbin/cupsd"
type=APPARMOR_DENIED msg=audit(1224193295.882:29): operation="inode_permission" requested_mask="::r" denied_mask="::r" fsuid=7 name="/proc/8343/net/dev" pid=8343 profile="/usr/sbin/cupsd"

chr1s@chris-desktop:~/src/system-config-samba$ apt-cache policy cups
cups:
  Installed: 1.3.9-1
  Candidate: 1.3.9-1
  Version table:
 *** 1.3.9-1 0
        500 http://archive.ubuntu.com intrepid/main Packages
        100 /var/lib/dpkg/status
chr1s@chris-desktop:~/src/system-config-samba$ apt-cache policy apparmor
apparmor:
  Installed: 2.3+1289-0ubuntu4
  Candidate: 2.3+1289-0ubuntu4
  Version table:
 *** 2.3+1289-0ubuntu4 0
        500 http://archive.ubuntu.com intrepid/main Packages
        100 /var/lib/dpkg/status

I still don't get those, at least not with something obvious like on cupsd startup, using lpstat -p, using the web interface, or enabling BrowseProtocols All. Do you have a recipe when those messages show up? What kind of printers are you using and how are they configured? What did you do when those messages appeared? Thank you!

Martin,

I'm not doing anything to trigger those messages - I haven't used my printer at all since using Intrepid, and I don't think anybody else has either. However, I do use the Turboprint cups driver for my printer (Epson Stylus Photo R800).

When I get a chance (probably not straight away), I will remove Turboprint and see if the errors go away.

I forgot to add - I do use cups-pdf too.

This is the only error in my /var/log/cups/error_log:

E [24/Oct/2008:18:30:34 +0100] Unable to bind socket for address 127.0.0.1:631 - Address already in use. However, the timestamp doesn't correspond with these latest errors in my audit.log, which all occured when I last booted the machine:

type=APPARMOR_DENIED msg=audit(1224870349.404:17): operation="inode_permission" requested_mask="r::" denied_mask="r::" fsuid=7 name="/proc/9685/net/" pid=9685 profile="/usr/sbin/cupsd"
type=APPARMOR_DENIED msg=audit(1224870350.440:18): operation="inode_permission" requested_mask="r::" denied_mask="r::" fsuid=7 name="/proc/9694/net/" pid=9694 profile="/usr/sbin/cupsd"
type=APPARMOR_DENIED msg=audit(1224870350.440:19): operation="socket_create" family="ax25" sock_type="dgram" protocol=0 pid=9694 profile="/usr/sbin/cupsd"
type=APPARMOR_DENIED msg=audit(1224870350.440:20): operation="socket_create" family="netrom" sock_type="seqpacket" protocol=0 pid=9694 profile="/usr/sbin/cupsd"
type=APPARMOR_DENIED msg=audit(1224870350.440:21): operation="socket_create" family="rose" sock_type="dgram" protocol=0 pid=9694 profile="/usr/sbin/cupsd"
type=APPARMOR_DENIED msg=audit(1224870350.440:22): operation="socket_create" family="ipx" sock_type="dgram" protocol=0 pid=9694 profile="/usr/sbin/cupsd"
type=APPARMOR_DENIED msg=audit(1224870350.440:23): operation="socket_create" family="appletalk" sock_type="dgram" protocol=0 pid=9694 profile="/usr/sbin/cupsd"
type=APPARMOR_DENIED msg=audit(1224870350.440:24): operation="socket_create" family="econet" sock_type="dgram" protocol=0 pid=9694 profile="/usr/sbin/cupsd"
type=APPARMOR_DENIED msg=audit(1224870350.440:25): operation="socket_create" family="ash" sock_type="dgram" protocol=0 pid=9694 profile="/usr/sbin/cupsd"
type=APPARMOR_DENIED msg=audit(1224870350.440:26): operation="socket_create" family="x25" sock_type="seqpacket" protocol=0 pid=9694 profile="/usr/sbin/cupsd"
type=APPARMOR_DENIED msg=audit(1224870350.440:27): operation="inode_permission" requested_mask="::r" denied_mask="::r" fsuid=7 name="/proc/9694/net/dev" pid=9694 profile="/usr/sbin/cupsd"

I am also seeing those message in the latest cups in intrepid (version 1.3.9-2). I believe that I have a standard setup except for a few IPP printers configured in /etc/cups/printers.conf.

Martin, if you still do not see those messages, could you try to add an IPP printer in /etc/cups/printers.conf ?

For instance:

DeviceURI ipp://cups-server:631/printers/my-printer

Ah, I did a fresh install of intrepid yesterday, and I see the errors in dmesg now, too. However, I can't reproduce them when doing sudo /etc/init.d/cups restart, so they only seem to happen on system start.

Got it now. It does not happen when cups starts up, but when something triggers its printer detection, such as jockey-gtk --check.

This can easily be reproduced by doing "lpinfo -v".

Fixed in bzr trunk.

Since upgrading to intrepid, I could no longer print to LPD printers on the network. Looking in my logs, I do see the same apparmor messages as being reported above. It seems that this bug is preventing me from being able to print on intrepid. This is a BIG regression for me.

I removed the usr.sbin.cupsd file from /etc/apparmor.d, restarted apparmor and printing starts working again.

When should we expect the proper fix to hit the repositories?

hi Ali,

Ali Sheikh [2008-11-04 15:45 -0000]:
> Since upgrading to intrepid, I could no longer print to LPD printers on
> the network. Looking in my logs, I do see the same apparmor messages as
> being reported above. It seems that this bug is preventing me from
> being able to print on intrepid. This is a BIG regression for me.

The messages which this bug is about are actually just a cosmetic
problem. They are from the bonjour network printer detection backend,
for unusual network protocols.

> I removed the usr.sbin.cupsd file from /etc/apparmor.d, restarted
> apparmor and printing starts working again.

OK, that indicates that you have a different bug, but it is related to
the profile. Can you please report a new bug, attach /var/log/kern.log
after a failed printing attempt, and assign it to me? ("pitti").
Thanks!

Nominating for intrepid SRU. Patch is obvious and safe (widening AppArmor profile permissions) and it is a regression compared to Hardy (whose kernel didn't have those fine-grained network access rules yet).

This bug was fixed in the package cups - 1.3.9-3

---------------
cups (1.3.9-3) experimental; urgency=low

  [ Till Kamppeter ]
  * debian/filters/pstopdf: Fixed several bugs in the pstopdf filter. First,
    removed the use of CUPS' pstops filter for inserting option settings. This
    also inserts PJL headers and then Ghostscript cannot convert the PostScript
    to PDF in the next step. Fixed also the sed magic so that the paper size
    and the margins get really read from the PPD and fixed the calculation of
    the top and bottom margins, they were exchanged. Fixes LP: #289759,
    LP: #292690, LP: #282186. Possible fix for LP #293883.

  [ Martin Pitt ]
  * debian/local/apparmor-profile: Allow dnssd backend to create various less
    common network protocols (x25, appletalk, etc.) for detection. Also allow
    it to read /proc/*/net/, which the bonjour avahi library apparently uses.
    (LP: #254022)

 -- Martin Pitt <email address hidden> Wed, 29 Oct 2008 11:41:38 +0100

Accepted into intrepid-proposed, please test and give feedback here. Please see https://wiki.ubuntu.com/Testing/EnableProposed for documentation how to enable and use -proposed. Thank you in advance!

I have tested it on two boxes, one not updated to -proposed (1.3.9-2) and one updated to -proposed (1.3.9-2ubuntu1). On the former the messages in /var/log/syslog appear, in the latter not.

Copied to intrepid-updates.

Hi.
I am facing this problem since one or two weeks again - maybe again a regression.
Removing usr.sbin.cups from apparmor and restarting apparmor + cups and it works again.
Using Intrepid.