Bug 738710 - Problem with systemd socket activation: IPv4 socket becomes unresponsive
Summary: Problem with systemd socket activation: IPv4 socket becomes unresponsive
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Fedora
Classification: Fedora
Component: cups
Version: 16
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
Assignee: Tim Waugh
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2011-09-15 15:37 UTC by Tim Waugh
Modified: 2011-10-19 04:42 UTC (History)
3 users (show)

Fixed In Version: cups-1.5.0-16.fc16
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2011-10-19 04:42:26 UTC


Attachments (Terms of Use)
strace lpstst -s (34.62 KB, text/plain)
2011-10-05 10:58 UTC, nucleo
no flags Details

Description Tim Waugh 2011-09-15 15:37:49 UTC
Description of problem:
After updating CUPS configuration using e.g. 'cupsctl --debug-logging', attempting to view http://localhost:631/ just sits waiting for a response.

Version-Release number of selected component (if applicable):
cups-1.5.0-6.fc16.x86_64

How reproducible:
100%

Steps to Reproduce:
1.View http://localhost:631/
2.Run cupsctl to make a change in the configuration
3.View http://localhost:631/
  
Actual results:
Second attempt to view the web interface fails.

Expected results:
No change.

Comment 1 Fedora Update System 2011-09-22 14:23:25 UTC
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

Comment 2 Fedora Update System 2011-09-24 20:50:31 UTC
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).

Comment 3 Fedora Update System 2011-09-28 18:52:16 UTC
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).

Comment 4 nucleo 2011-10-02 21:21:50 UTC
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.

Comment 5 Tim Waugh 2011-10-03 10:16:23 UTC
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)?

Comment 6 nucleo 2011-10-03 11:43:27 UTC
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/

Comment 7 nucleo 2011-10-03 11:51:34 UTC
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/

Comment 8 Tim Waugh 2011-10-03 11:55:48 UTC
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.

Comment 9 nucleo 2011-10-03 13:02:51 UTC
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.

Comment 10 Fedora Update System 2011-10-04 20:46:17 UTC
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).

Comment 11 nucleo 2011-10-04 23:12:25 UTC
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.

Comment 12 Tim Waugh 2011-10-05 09:00:00 UTC
(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?

Comment 13 nucleo 2011-10-05 10:58:27 UTC
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 ?

Comment 14 Tim Waugh 2011-10-05 11:57:08 UTC
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.

Comment 15 nucleo 2011-10-05 12:12:09 UTC
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?

Comment 16 Tim Waugh 2011-10-05 13:05:09 UTC
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.

Comment 17 Fedora Update System 2011-10-06 21:21:28 UTC
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).

Comment 18 Fedora Update System 2011-10-08 23:34:15 UTC
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).

Comment 19 Fedora Update System 2011-10-12 16:48:52 UTC
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).

Comment 20 Fedora Update System 2011-10-19 04:42:26 UTC
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.


Note You need to log in before you can comment on or make changes to this bug.