selinux enforced (Ubuntu Hardy) : printer doesn't print : cupsd: Unable to open log file "/var/log/cups/access_log" - Permission denied

[Tchang7]

Binary package hint: selinux-policy-refpolicy-cups

With selinux permissive, I print without problem. When enforced, I can't print. I click on the printer icon in the upper bar, a window opens indicating that the document is in queue but time passes and nothing happens. Syslog gives the following:

Oct 29 05:24:58 localhostlouis cupsd: Unable to open log file "/var/log/cups/access_log" - Permission denied
Oct 29 05:24:58 localhostlouis kernel: [ 5311.663595] audit(1225272298.789:153): avc: denied { read append } for pid=7046 comm="cupsd" name="access_log" dev=sdb3 ino=979382 scontext=system_u:system_r:cupsd_t tcontext=system_u:object_r:file_t tclass=file

I checked the owner:group permissions for the file access_log and they are "root:lp 100640"

I'm not sure it's a bug, I'm relatively new to Linux and I don't know anything about selinux. I did a search on Google with the terms "ubuntu selinux printer problem" and there are very few results.

I use selinux-policy-refpolicy-cups 20071214 on Ubuntu Hardy 32bits on an Intel Core2 computer with an inkjet printer HP Photosmart C6180 with HPLIP Toolbox installed.

ProblemType: Bug
Architecture: i386
Date: Wed Oct 29 18:33:46 2008
DistroRelease: Ubuntu 8.04
ExecutablePath: /usr/bin/yelp
NonfreeKernelModules: nvidia ath_hal
Package: yelp 2.22.1-0ubuntu2.8.04.3
PackageArchitecture: i386
ProcEnviron:
 PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games
 LANG=fr_CA.UTF-8
 SHELL=/bin/bash
SourcePackage: yelp
Uname: Linux 2.6.24-21-generic i686

[Matt Anderson (mra-malloc)]

The audit message shows that the context of /var/log/cups/access_log is tcontext=system_u:object_r:file_t, it should cupsd_log_t. `restorecon -rv /` should fix that (along with any other mislabeled files).

[Tchang7 (ano-nyme)]

Thank you for your response. I had to repeat the command because of an "error in pipe". Many many files were relabeled. Even with these changes, I cannot print. The printer can't connect:

Oct 29 22:53:19 localhostlouis Photosmart_C6100_series?serial=[...]: io/hpmud/musb.c 1058: unable to open hp:/usb/Photosmart_C6100_series?serial=MY6AFH531V04KR
Oct 29 22:53:19 localhostlouis Photosmart_C6100_series?serial=[...]: prnt/backend/hp.c 496: unable to connect hpssd socket 2207: Connection refused
Oct 29 22:53:19 localhostlouis Photosmart_C6100_series?serial=[...]: prnt/backend/hp.c 636: INFO: open device failed; will retry in 30 seconds...
Oct 29 22:53:19 localhostlouis kernel: [ 2309.251061] audit(1225335199.273:620): avc: denied { read } for pid=8946 comm="hp" name="001" dev=tmpfs ino=5700 scontext=system_u:system_r:cupsd_t tcontext=system_u:object_r:usb_device_t tclass=chr_file
Oct 29 22:53:19 localhostlouis kernel: [ 2309.251103] audit(1225335199.273:621): avc: denied { read } for pid=8946 comm="hp" name="004" dev=tmpfs ino=5938 scontext=system_u:system_r:cupsd_t tcontext=system_u:object_r:usb_device_t tclass=chr_file
Oct 29 22:53:19 localhostlouis kernel: [ 2309.251127] audit(1225335199.273:622): avc: denied { read } for pid=8946 comm="hp" name="001" dev=tmpfs ino=5688 scontext=system_u:system_r:cupsd_t tcontext=system_u:object_r:usb_device_t tclass=chr_file
Oct 29 22:53:19 localhostlouis kernel: [ 2309.251162] audit(1225335199.273:623): avc: denied { read } for pid=8946 comm="hp" name="002" dev=tmpfs ino=5882 scontext=system_u:system_r:cupsd_t tcontext=system_u:object_r:usb_device_t tclass=chr_file
Oct 29 22:53:19 localhostlouis kernel: [ 2309.251187] audit(1225335199.273:624): avc: denied { read } for pid=8946 comm="hp" name="001" dev=tmpfs ino=5656 scontext=system_u:system_r:cupsd_t tcontext=system_u:object_r:usb_device_t tclass=chr_file
Oct 29 22:53:19 localhostlouis kernel: [ 2309.251222] audit(1225335199.273:625): avc: denied { read } for pid=8946 comm="hp" name="003" dev=tmpfs ino=6038 scontext=system_u:system_r:cupsd_t tcontext=system_u:object_r:usb_device_t tclass=chr_file
Oct 29 22:53:19 localhostlouis kernel: [ 2309.251245] audit(1225335199.273:626): avc: denied { read } for pid=8946 comm="hp" name="002" dev=tmpfs ino=5981 scontext=system_u:system_r:cupsd_t tcontext=system_u:object_r:usb_device_t tclass=chr_file
Oct 29 22:53:19 localhostlouis kernel: [ 2309.251268] audit(1225335199.273:627): avc: denied { read } for pid=8946 comm="hp" name="001" dev=tmpfs ino=5649 scontext=system_u:system_r:cupsd_t tcontext=system_u:object_r:usb_device_t tclass=chr_file
Oct 29 22:53:19 localhostlouis kernel: [ 2309.251302] audit(1225335199.273:628): avc: denied { read } for pid=8946 comm="hp" name="001" dev=tmpfs ino=5642 scontext=system_u:system_r:cupsd_t tcontext=system_u:object_r:usb_device_t tclass=chr_file
Oct 29 22:53:19 localhostlouis kernel: [ 2309.251333] audit(1225335199.273:629): avc: denied { read write } for pid=8946 comm="hp" name="004" dev=tmpfs ino=5776 scontext=system_u:system_r:cupsd_t tcontext=system_u:object_r:usb_device_t tclass=chr_file
Oct 29 22:53:19 localhostlouis kernel: [ 2309.251349] ...

[Tchang7 (ano-nyme)]

Thank you for your response. I had to repeat the command because of an "error in pipe". Many many files were relabeled. Even with these changes, I cannot print. The printer can't connect:

Oct 29 22:53:19 localhostlouis Photosmart_C6100_series?serial=[...]: io/hpmud/musb.c 1058: unable to open hp:/usb/Photosmart_C6100_series?serial=MY6AFH531V04KR
Oct 29 22:53:19 localhostlouis Photosmart_C6100_series?serial=[...]: prnt/backend/hp.c 496: unable to connect hpssd socket 2207: Connection refused
Oct 29 22:53:19 localhostlouis Photosmart_C6100_series?serial=[...]: prnt/backend/hp.c 636: INFO: open device failed; will retry in 30 seconds...
Oct 29 22:53:19 localhostlouis kernel: [ 2309.251061] audit(1225335199.273:620): avc: denied { read } for pid=8946 comm="hp" name="001" dev=tmpfs ino=5700 scontext=system_u:system_r:cupsd_t tcontext=system_u:object_r:usb_device_t tclass=chr_file
Oct 29 22:53:19 localhostlouis kernel: [ 2309.251103] audit(1225335199.273:621): avc: denied { read } for pid=8946 comm="hp" name="004" dev=tmpfs ino=5938 scontext=system_u:system_r:cupsd_t tcontext=system_u:object_r:usb_device_t tclass=chr_file
Etc.

I think it could be a CUPS problem revealed by SELinux: on http://linux.derkeiler.com/pdf/Mailing-Lists/Ubuntu/2006-07/msg01692.pdf, it says:

"i am seeing tons of these in my log
Jul 6 10:01:14 lares cupsd: Unable to open log file "/var/log/cups/error_log"
− Permission denied
last message repeated 189 times
This tells us that
a) the logfile hasn't the right rights
or
b) the cupsd is running with the wrong user
cupsys"

[Matt Anderson (mra-malloc)]

Your audit message says the target context is usb_device_t, I think it should be printer_device_t. restorecon should have caught this, it might need to be updated in the policy.

If it works in permissive mode then we know that it is an SELinux issue. If it still is broken then it might be the file permissions or runas user, but from what you've posted here I think there is at least still a mislabeled file getting in the way.

[Tchang7 (ano-nyme)]

The printer definitely works when selinux is permissive. With selinux enforced, I repeated many times `restorecon -rv /` and the following lines continue to appear, as if the modifications were not registered when executed:

restorecon reset /usr/lib/cups/backend-available/dnssd context system_u:object_r:bin_t->system_u:object_r:lib_t
restorecon reset /usr/lib/cups/backend-available/parallel context system_u:object_r:bin_t->system_u:object_r:lib_t
restorecon reset /usr/lib/cups/backend-available/snmp context system_u:object_r:bin_t->system_u:object_r:lib_t
restorecon reset /usr/lib/cups/backend-available/scsi context system_u:object_r:bin_t->system_u:object_r:lib_t
restorecon reset /usr/lib/cups/backend-available/ipp context system_u:object_r:bin_t->system_u:object_r:lib_t
restorecon reset /usr/lib/cups/backend-available/lpd context system_u:object_r:bin_t->system_u:object_r:lib_t
restorecon reset /usr/lib/cups/backend-available/serial context system_u:object_r:bin_t->system_u:object_r:lib_t
restorecon reset /usr/lib/cups/backend-available/usb context system_u:object_r:bin_t->system_u:object_r:lib_t
restorecon reset /usr/lib/cups/backend-available/socket context system_u:object_r:bin_t->system_u:object_r:lib_t
restorecon reset /usr/lib/cups/backend/dnssd context system_u:object_r:lib_t->system_u:object_r:bin_t
restorecon reset /usr/lib/cups/backend/parallel context system_u:object_r:lib_t->system_u:object_r:bin_t
restorecon reset /usr/lib/cups/backend/snmp context system_u:object_r:lib_t->system_u:object_r:bin_t
restorecon reset /usr/lib/cups/backend/scsi context system_u:object_r:lib_t->system_u:object_r:bin_t
restorecon reset /usr/lib/cups/backend/ipp context system_u:object_r:lib_t->system_u:object_r:bin_t
restorecon reset /usr/lib/cups/backend/lpd context system_u:object_r:lib_t->system_u:object_r:bin_t
restorecon reset /usr/lib/cups/backend/serial context system_u:object_r:lib_t->system_u:object_r:bin_t
restorecon reset /usr/lib/cups/backend/usb context system_u:object_r:lib_t->system_u:object_r:bin_t
restorecon reset /usr/lib/cups/backend/socket context system_u:object_r:lib_t->system_u:object_r:bin_t

[Tchang7 (ano-nyme)]

When I indicated that selinux was set in permissive mode, in fact I was diseabling it by changing to selinux=0 on boot.

[Laurent Bigonville (bigon)]

This is a pretty old bug, I quickly look at this with refpolicy 2:2.20131214-1 and all the avc denials mentioned here should now be granted

Feel free to reopen if you are still experiencing this bug