Bug 796324

Summary: Printing broke with cups 1.5.2-1.fc16 update
Product: [Fedora] Fedora Reporter: Jason Tibbitts <j>
Component: cupsAssignee: Tim Waugh <twaugh>
Status: CLOSED NOTABUG QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 16CC: Bert.Deknuydt, jpopelka, twaugh
Target Milestone: ---   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2012-02-23 17:28:05 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:

Description Jason Tibbitts 2012-02-22 17:16:39 UTC 
I'm trying to understand why printing broken on all 100+ of my F16 desktops last night, and I've come to a strange set of circumstances I don't understand.

cups updated automatically to 1.5.2-1.fc16 last night (from 1.5.0-22.fc16).
lpstat -t after the update produces:

scheduler is not running
lpstat: error - PRINTER environment variable names non-existent destination "rm660".
lpstat: Connection refused
lpstat: Connection refused
lpstat: Connection refused
lpstat: Connection refused
lpstat: Connection refused

The cups server is running at this point.

Restarting the cups server does not help.

ausearch shows no AVCs, and the problem does not go away in permissive mode.

Downgrading to the previous 1.5.0-22 packages does not help.

system-config-printer indicates that it also cannot connect to the server.

strace shows that lpstat is trying to connect to /var/run/cups/cups.sock, which exists:

srw-rw-rw-. 1 root root 0 Feb 15 12:18 /var/run/cups/cups.sock=
srw-rw-rw-. root root system_u:object_r:cupsd_var_run_t:s0 /var/run/cups/cups.sock=

Removing this file causes things to work immediately (no server restart needed).  Note from the above date that the file existed before the update, and things did indeed work yesterday.

I am at a loss.  I'll try to keep one machine in this messed-up state in case you need me to test anything, but I'm not even sure what information I can provide to you.
Comment 1 Tim Waugh 2012-02-23 12:33:30 UTC 
Does 'yum history' say that other packages were upgraded at the same time?  Perhaps there's an SELinux dontaudit rule causing problems.

Please attach /etc/cups/cupsd.conf.

Are there any interesting messages in /var/log/cups/error_log?
Comment 2 Jason Tibbitts 2012-02-23 16:31:45 UTC 
There were a few other updates but nothing looks remotely related to either cups or selinux.  I'll paste the transaction at the end.

The error log is devoid of anything different from its usual startup; indeed, cupsd appears to be running just fine.  It does complain about "failed to find device: cups-foo" for every printer, but searching shows that's related to color correction.  The printcap file is updated properly with whatever is found from the network, and (though I didn't save their state so I can't test them now) F16 machines which were sharing printers continued to share them.  I would wager that I'd have no problem printing to them while they were in this state.

selinux is in permissive mode so I figured it wouldn't be involved, but I did semodule -DB to disable dontaudit rules and the behavior does not change.  (Nor is anything related logged.)

cupsd.conf is pretty simple and is pasted below.

I think the fundamental issue is that cupsd isn't listening on /var/run/cups/cups.sock; lsof shows that it's listening to a few sockets but none with names in the filesystem:

lsof -a -p 30547 -U
COMMAND   PID USER   FD   TYPE             DEVICE SIZE/OFF    NODE NAME
cupsd   30547 root    1u  unix 0xffff880228aa9040      0t0 2990974 socket
cupsd   30547 root    2u  unix 0xffff880228aa9040      0t0 2990974 socket
cupsd   30547 root    9u  unix 0xffff880228b1ea40      0t0 2979645 socket
cupsd   30547 root   13u  unix 0xffff880228b1c000      0t0 2979649 socket

lpstat (and lpr and system-config-printer) will, upon seeing cups.sock in the right place, attempt to connect to it and nothing else. This fails because while there is a socket there, nothing is listening to the other end.  Removing the socket file solves the problem.  What I don't get is how the file came to exist and why it didn't cause any problems until now.

LogLevel info
Printcap /etc/printcap
Port 631
 
<Location />
Order Deny,Allow
Deny From All
Allow From 127.0.0.1
Allow From 129.7.128.2
</Location>
 
<Location /admin>
AuthType Basic
AuthClass System
Order Deny,Allow
Deny From All
Allow From 127.0.0.1
Allow From 129.7.128.2
</Location>

Transaction ID : 26
Begin time     : Wed Feb 22 04:29:08 2012
Begin rpmdb    : 2076:82b4b3e91217adc55d74ef6c13bc016c061403b5
End time       :            04:30:04 2012 (56 seconds)
End rpmdb      : 2076:8b57ad29a77dc9dd7d894c47ff77581974cdb3f5
User           : root <root>
Return-Code    : Success
Command Line   : -e 0 -d 0 -y shell /etc/yum/yum-daily.yum
Additional non-default information stored: 1
Transaction performed with:
    Installed     rpm-4.9.1.2-5.fc16.x86_64      @updates
    Installed     yum-3.4.3-7.fc16.noarch        @math-updates
    Installed     yum-presto-0.7.1-1.fc16.noarch @anaconda-0
Packages Altered:
    Updated cups-1:1.5.0-22.fc16.x86_64              ?
    Update       1:1.5.2-1.fc16.x86_64               @updates
    Updated cups-libs-1:1.5.0-22.fc16.i686           ?
    Updated cups-libs-1:1.5.0-22.fc16.x86_64         ?
    Update            1:1.5.2-1.fc16.i686            @updates
    Update            1:1.5.2-1.fc16.x86_64          @updates
    Updated hdf5-1.8.7-3.fc16.x86_64                 ?
    Update       1.8.7-5.fc16.x86_64                 @updates
    Updated httpd-2.2.21-1.fc16.x86_64               @?fedora
    Update        2.2.22-1.fc16.x86_64               @updates
    Updated httpd-tools-2.2.21-1.fc16.x86_64         @?fedora
    Update              2.2.22-1.fc16.x86_64         @updates
    Updated ibus-1.4.0-17.fc16.x86_64                ?
    Update       1.4.1-1.fc16.x86_64                 @updates
    Updated ibus-gtk2-1.4.0-17.fc16.x86_64           ?
    Update            1.4.1-1.fc16.x86_64            @updates
    Updated ibus-gtk3-1.4.0-17.fc16.x86_64           ?
    Update            1.4.1-1.fc16.x86_64            @updates
    Updated ibus-libs-1.4.0-17.fc16.x86_64           ?
    Update            1.4.1-1.fc16.x86_64            @updates
    Updated libpng-2:1.2.46-1.fc16.i686              @?fedora
    Updated libpng-2:1.2.46-1.fc16.x86_64            @?fedora
    Update         2:1.2.46-2.fc16.i686              @updates
    Update         2:1.2.46-2.fc16.x86_64            @updates
    Updated libpng-devel-2:1.2.46-1.fc16.x86_64      @?fedora
    Update               2:1.2.46-2.fc16.x86_64      @updates
    Updated libtalloc-2.0.6-1.fc16.x86_64            @?fedora
    Update            2.0.7-4.fc16.x86_64            @updates
    Updated libtevent-0.9.13-1.fc16.x86_64           @?fedora
    Update            0.9.15-1.fc16.x86_64           @updates
    Updated mesa-dri-drivers-7.11.2-1.fc16.i686      ?
    Updated mesa-dri-drivers-7.11.2-1.fc16.x86_64    ?
    Update                   7.11.2-3.fc16.i686      @updates
    Update                   7.11.2-3.fc16.x86_64    @updates
    Updated mesa-dri-filesystem-7.11.2-1.fc16.i686   ?
    Updated mesa-dri-filesystem-7.11.2-1.fc16.x86_64 ?
    Update                      7.11.2-3.fc16.i686   @updates
    Update                      7.11.2-3.fc16.x86_64 @updates
    Updated mesa-libGL-7.11.2-1.fc16.i686            ?
    Updated mesa-libGL-7.11.2-1.fc16.x86_64          ?
    Update             7.11.2-3.fc16.i686            @updates
    Update             7.11.2-3.fc16.x86_64          @updates
    Updated mesa-libGL-devel-7.11.2-1.fc16.x86_64    ?
    Update                   7.11.2-3.fc16.x86_64    @updates
    Updated mesa-libGLU-7.11.2-1.fc16.i686           ?
    Updated mesa-libGLU-7.11.2-1.fc16.x86_64         ?
    Update              7.11.2-3.fc16.i686           @updates
    Update              7.11.2-3.fc16.x86_64         @updates
    Updated mesa-libGLU-devel-7.11.2-1.fc16.x86_64   ?
    Update                    7.11.2-3.fc16.x86_64   @updates
    Updated mesa-libOSMesa-7.11.2-1.fc16.x86_64      ?
    Update                 7.11.2-3.fc16.x86_64      @updates
    Updated systemtap-sdt-devel-1.6-1.fc16.x86_64    @?fedora
    Update                      1.7-1.fc16.x86_64    @updates
    Updated xulrunner-10.0.1-1.fc16.x86_64           ?
    Update            10.0.1-3.fc16.x86_64           @updates
Comment 3 Tim Waugh 2012-02-23 16:46:39 UTC 
Is that all that's in cupsd.conf?  Compare it to /etc/cups/cupsd.conf.default.

In particular there's no line telling it to listen on the socket...

Listen /var/run/cups/cups.sock
Comment 4 Jason Tibbitts 2012-02-23 17:28:05 UTC 
It's the cups configuration I have used for... a very long time.  Probably from Red Hat Linux times.  Back when you had to drop in a configuration file so that network printing would work at all.  Always worked OK until yesterday morning.

I guess it's an age-old problem.  When I migrate to a new Fedora release I just make sure that it works and don't really have time to see how every custom configuration has deviated from the default one, or if the default one has become useful in my environment.  And of course you can't predict with each update what kind of hilariously outdated or broken configuration files people might be using.

Guess this is NOTABUG.  Thanks for your assistance.