Bug 738710

cups-1.5.0-9.fc16 has been submitted as an update for Fedora 16.
https://admin.fedoraproject.org/updates/cups-1.5.0-9.fc16

Package cups-1.5.0-9.fc16:
* should fix your issue,
* was pushed to the Fedora 16 testing repository,
* should be available at your local mirror within two days.
Update it with:
# su -c 'yum update --enablerepo=updates-testing cups-1.5.0-9.fc16'
as soon as you are able to.
Please go to the following url:
https://admin.fedoraproject.org/updates/cups-1.5.0-9.fc16
then log in and leave karma (feedback).

Package cups-1.5.0-10.fc16:
* should fix your issue,
* was pushed to the Fedora 16 testing repository,
* should be available at your local mirror within two days.
Update it with:
# su -c 'yum update --enablerepo=updates-testing cups-1.5.0-10.fc16'
as soon as you are able to.
Please go to the following url:
https://admin.fedoraproject.org/updates/cups-1.5.0-10.fc16
then log in and leave karma (feedback).

http://localhost:631/ can not be opened with cups-1.5.0-10.fc17 just after Rawhide machine started.
Browser says "Connection to localhost established. Waiting for reply...".
But no reply received.

nucleo: it works fine for me in F-16.  Can you try stopping the cups.service, cups.socket, and cups.path units, then starting them (in reverse order)?

I have running and working fine cups.service before this update.
To test this update I disabled cups.service (link to cups.service was removed) and enabled it again (link to cups.service, cups.socket, and cups.path created) and rebooted.
After reboot browser can't open http://localhost:631/, in error_log "Unable to bind socket 127.0.0.1:631 - Address already in use".
If I do
systemctl stop cups.socket
systemctl stop cups.service
systemctl start cups.service

then browser can open http://localhost:631/

If I run
systemctl stop cups.service
systemctl stop cups.socket
systemctl stop cups.path
systemctl start cups.path
systemctl start cups.socket
systemctl start cups.service

then again browser can't open http://localhost:631/

Does 'lpstat -s' work, or do you get an error?

I'd like to see what /var/log/cups/error_log looks like when you start CUPS as in comment #7.  To do that, please run these commands:

systemctl stop cups.service
systemctl stop cups.socket
systemctl stop cups.path
>/var/log/cups/error_log
systemctl start cups.path
systemctl start cups.socket
systemctl start cups.service

and then attach /var/log/cups/error_log to this bug report.  Thanks.

I cleaned cups logs and rebooted. After reboot all logs still was empty.
'systemctl | grep cups' shows:
cups.path                 loaded active waiting       CUPS Printer Service Spool
cups.socket               loaded active listening     CUPS Printing Service Sockets

When running 'lpstat -s' there was message:

WARNING: no socket to connect to
no system default destination <- this was after some delay
lpstat: Unknown

and appeared messages in error_log:

E [03/Oct/2011:15:42:24 +0300] systemd_checkin: Unable to get local address - Invalid argument
E [03/Oct/2011:15:42:24 +0300] systemd_checkin: Unable to get local address - Invalid argument
E [03/Oct/2011:15:42:24 +0300] Unable to bind socket for address [v1.::1]:631 - Address already in use.
E [03/Oct/2011:15:42:24 +0300] Unable to bind socket for address 127.0.0.1:631 - Address already in use.

The same messages in error_log appeared after I try to open http://localhost:631/ in browser.

When I run 'lpstat -s' next time there was other messages (without any delay):

WARNING: no socket to connect to
system default destination: cups-pdf
device for cups-pdf: ipp://192.168.0.1:631/printers/Cups-PDF

After I run 'systemctl stop cups.service' added new messages in error_log:

E [03/Oct/2011:15:48:33 +0300] systemd_checkin: Unable to get local address - Invalid argument
E [03/Oct/2011:15:48:33 +0300] systemd_checkin: Unable to get local address - Invalid argument
E [03/Oct/2011:15:48:33 +0300] Unable to bind socket for address [v1.::1]:631 - Address already in use.
E [03/Oct/2011:15:48:33 +0300] Unable to bind socket for address 127.0.0.1:631 - Address already in use.

After I run 'systemctl stop cups.socket', 'systemctl stop cups.path' 'systemctl start cups.path' was no any messages.

After I run 'systemctl start cups.socket' was this message:

Job failed. See system logs and 'systemctl status' for details.

And after 'systemctl start cups.service' was no any messages.

Package cups-1.5.0-13.fc16:
* should fix your issue,
* was pushed to the Fedora 16 testing repository,
* should be available at your local mirror within two days.
Update it with:
# su -c 'yum update --enablerepo=updates-testing cups-1.5.0-13.fc16'
as soon as you are able to.
Please go to the following url:
https://admin.fedoraproject.org/updates/cups-1.5.0-13.fc16
then log in and leave karma (feedback).

cups-1.5.0-13.fc17 looks better.

After system started I run 'lpstat -s':

WARNING: no socket to connect to
system default destination: cups-pdf <- here was about 3 sec delay
device for cups-pdf: ipp://192.168.0.1:631/printers/Cups-PDF

Next time this  runs without any delay.
But in error_log appeared messages:

W [05/Oct/2011:01:35:49 +0300] failed to find device: cups-cups-pdf
E [05/Oct/2011:01:35:53 +0300] Unable to bind socket for address [v1.::1]:631 - Address already in use.
E [05/Oct/2011:01:35:53 +0300] Unable to bind socket for address 127.0.0.1:631 - Address already in use.


cups-pdf here is just name of network printer on host 192.168.0.1. 
Why "cups-cups-pdf" appeared now in error_log?
But printing works fine.
After print job finished this messaged added in error_log:

W [05/Oct/2011:01:37:17 +0300] [Job 6] no socket to connect to
W [05/Oct/2011:01:37:26 +0300] failed to CreateProfile: org.freedesktop.ColorManager.AlreadyExists:profile id 'cups-pdf-Gray..' already exists
W [05/Oct/2011:01:37:26 +0300] failed to CreateProfile: org.freedesktop.ColorManager.AlreadyExists:profile id 'cups-pdf-RGB..' already exists
W [05/Oct/2011:01:37:26 +0300] failed to CreateDevice: org.freedesktop.ColorManager.AlreadyExists:device id 'cups-cups-pdf' already exists

If I try to open http://localhost:631/ just after system booted then there is also about 3 sec delay and then "Forbidden - CUPS v1.5.0" page opened instead of CUPS web interface.

(In reply to comment #11)
> cups-1.5.0-13.fc17 looks better.
> 
> After system started I run 'lpstat -s':
> 
> WARNING: no socket to connect to

Oh, that looks bad.  But weirdly, I can't find this anywhere in the CUPS source.

The "failed to find device:" message is harmless; it's just from the colord support.

Could you please run 'strace lpstat -s' so we can see where the "no socket to connect to" message is coming from?

Created attachment 526462 [details]
strace lpstst -s

3 seconds delay was after "poll([{fd=4, events=POLLIN}], 1, 1000)  = 0 (Timeout)"

Why "Forbidden" displayed on http://localhost:631 ?

OK, the "WARNING: no socket to connect to" message comes from gnome-keyring and is something to do with PKCS#11.

I think that "localhost" is resolving to something other than [::1] for you, even when IPv6 is enabled.

Web interface opened with address http://[::1]:631 but forbidden with http://127.0.0.1:631 and http://localhost:631 and http://localhost.localdomain:631.
Why it can be opened only with IPv6 localhost address?

And what about 3 seconds delay before first try to run lpstat or open web interface, is this delay should be?

This bug report is already quite crowded with issues.  Let's keep this one as "IPv4 socket becomes unresponsive" (i.e. because CUPS closed its socket on restart, now fixed), and move other issues to separate bugs.

I've filed "127.0.0.1 not seen as loopback address" as bug #743585.

Please file the 3-second-delay as a separate bug.

Package cups-1.5.0-14.fc16:
* should fix your issue,
* was pushed to the Fedora 16 testing repository,
* should be available at your local mirror within two days.
Update it with:
# su -c 'yum update --enablerepo=updates-testing cups-1.5.0-14.fc16'
as soon as you are able to.
Please go to the following url:
https://admin.fedoraproject.org/updates/FEDORA-2011-13168
then log in and leave karma (feedback).

Package cups-1.5.0-15.fc16:
* should fix your issue,
* was pushed to the Fedora 16 testing repository,
* should be available at your local mirror within two days.
Update it with:
# su -c 'yum update --enablerepo=updates-testing cups-1.5.0-15.fc16'
as soon as you are able to.
Please go to the following url:
https://admin.fedoraproject.org/updates/FEDORA-2011-13168
then log in and leave karma (feedback).

Package cups-1.5.0-16.fc16:
* should fix your issue,
* was pushed to the Fedora 16 testing repository,
* should be available at your local mirror within two days.
Update it with:
# su -c 'yum update --enablerepo=updates-testing cups-1.5.0-16.fc16'
as soon as you are able to.
Please go to the following url:
https://admin.fedoraproject.org/updates/FEDORA-2011-13168
then log in and leave karma (feedback).

cups-1.5.0-16.fc16 has been pushed to the Fedora 16 stable repository.  If problems still persist, please make note of it in this bug report.