Bug 864970

This also applies to hplip-3.12.4-1.el6.

+++ This bug was initially created as a clone of Bug #743593 +++

Created attachment 526489 [details]
strace lpstst -s

Description of problem:
There is 3-second delay when running 'lpstat -s' just after system started or when opening web interface http://localhost:631

Version-Release number of selected component (if applicable):
cups-1.5.0-13.fc17


Steps to Reproduce:
1. Restart system
2. Run 'lpstat -s'
3.
  
Actual results:
WARNING: no socket to connect to
system default destination: cups-pdf <- before this messge was 3-seconds delay 
device for cups-pdf: ipp://192.168.0.1:631/printers/Cups-PDF


Expected results:
No delay.

Additional info:
3-second delay was after "poll([{fd=4, events=POLLIN}], 1, 1000)  = 0
(Timeout)" in attached output of 'strace lpstat -s'

--- Additional comment from twaugh on 2011-10-10 12:08:03 EDT ---

It looks like the delay might be on the scheduler side.  Could you please run 'strace -ttp ...' on the cupsd process while you run 'lpstat -s'?

--- Additional comment from alekcejk on 2011-10-10 12:16:44 EDT ---

cupsd not running before first run 'lpstat -s' so how can I know PID of cupsd for strace?

--- Additional comment from twaugh on 2011-10-10 12:27:36 EDT ---

It should be running, because the %post scriptlet enables the service unit.

If this system has been updated from F-16 Alpha, enable the service with:

systemctl enable cups.service

In any case, once you run lpstat -s once, cupsd will be running, won't it?  So just run it once, then run strace on cupsd.

--- Additional comment from alekcejk on 2011-10-10 13:58:58 EDT ---

cups.service enabled but cupsd process not stared before first run 'lpstat -s'.
cups.service is not in /etc/systemd/system/multi-user.target.wants or /etc/systemd/system/basic.target.wants but in /etc/systemd/system/printer.target.wants so it not starts at boot time.

--- Additional comment from alekcejk on 2011-10-10 14:06:49 EDT ---

Created attachment 527287 [details]
sctrace -ttp cupsd

I was able to make strace when running second time 'lpstat -s' (was no any delay delay) for cupsd process that already running after first run of 'lpstat -s'.

--- Additional comment from alekcejk on 2011-10-10 14:08:30 EDT ---

But still don't know how to do this when cupsd not started.

--- Additional comment from twaugh on 2011-10-11 07:44:19 EDT ---

I wonder if the delay is due to socket activation, i.e. for whatever reason on your machine, cups isn't started at boot, so it is started on demand and that takes the amount of time you're seeing.

Please run 'yum reinstall cups'.  The cups.service unit ought to be enabled, and it currently isn't for you (probably because of bug #731421, long since fixed).

After you've done that, please (a) reboot, then (b) run time lpstat -s.  If it still takes a long time, show me the output of these commands:

systemctl status cups.socket
systemctl status cups.service

--- Additional comment from alekcejk on 2011-10-11 14:40:10 EDT ---

Reinstalled.

Before running 'lpstat -s':

cups.socket - CUPS Printing Service Sockets
          Loaded: loaded (/lib/systemd/system/cups.socket; enabled)
          Active: active (listening) since Tue, 11 Oct 2011 20:48:08 +0300; 48min ago
          CGroup: name=systemd:/system/cups.socket

cups.service - CUPS Printing Service
          Loaded: loaded (/lib/systemd/system/cups.service; enabled)
          Active: inactive (dead)
          CGroup: name=systemd:/system/cups.service

After running 'lpstat -s':

cups.socket - CUPS Printing Service Sockets
          Loaded: loaded (/lib/systemd/system/cups.socket; enabled)
          Active: active (running) since Tue, 11 Oct 2011 20:48:08 +0300; 49min ago
          CGroup: name=systemd:/system/cups.socket

cups.service - CUPS Printing Service
          Loaded: loaded (/lib/systemd/system/cups.service; enabled)
          Active: active (running) since Tue, 11 Oct 2011 21:36:59 +0300; 13s ago
        Main PID: 5829 (cupsd)
          CGroup: name=systemd:/system/cups.service
                  └ 5829 /usr/sbin/cupsd -f


$ time lpstat -s
system default destination: Cups-PDF
device for Cups-PDF: cups-pdf:/
device for ML-1520: usb://Samsung/ML-1520

real    0m3.959s
user    0m0.005s
sys     0m0.007s

--- Additional comment from twaugh on 2011-10-12 08:20:36 EDT ---

I think I see what's going on.

Could you please attach the output of 'systemctl show printer.target'?

--- Additional comment from alekcejk on 2011-10-12 08:30:35 EDT ---

Id=printer.target
Names=printer.target
Wants=cups.service
Conflicts=shutdown.target
Description=Printer
LoadState=loaded
ActiveState=inactive
SubState=dead
FragmentPath=/lib/systemd/system/printer.target
UnitFileState=static
InactiveExitTimestampMonotonic=0
ActiveEnterTimestampMonotonic=0
ActiveExitTimestampMonotonic=0
InactiveEnterTimestampMonotonic=0
CanStart=yes
CanStop=yes
CanReload=no
CanIsolate=no
StopWhenUnneeded=yes
RefuseManualStart=no
RefuseManualStop=no
AllowIsolate=no
DefaultDependencies=yes
OnFailureIsolate=no
IgnoreOnIsolate=no
IgnoreOnSnapshot=no
NeedDaemonReload=no
JobTimeoutUSec=0
ConditionTimestampMonotonic=0
ConditionResult=no

--- Additional comment from twaugh on 2011-10-12 09:21:00 EDT ---

OK.  When I try it, I have an additional line:

WantedBy=sys-devices-pnp0-00:07-printer-lp0.device

I think the reason for that is that this machine has a parallel port.  Does yours?

The cups.service unit file does not have WantedBy=multi-user.target as many other services do, but instead has WantedBy=printer.target.  This is a special target which is started when a USB or parallel port printer is connected.

So this fulfils the requirements of:
* starting on-demand when a printer is connected
* starting on-demand when there are jobs queued
* starting on-demand when a client connects to the socket

The short delay (only once per boot) is due to the service starting up.

System administrators who want the CUPS service to be running for the benefit of network users must manually perform this step:

ln -s /lib/systemd/system/cups.service /etc/systemd/system/multi-user.target.wants/

http://0pointer.de/blog/projects/socket-activation2.html

--- Additional comment from alekcejk on 2011-10-12 09:35:10 EDT ---

I have unused parallel port, printer connected to USB.
cups service started when printer connected.

What reason to not run cups at boot time?
Is it requires too much memory or takes much time (maybe should not because of parallel services starting)?

--- Additional comment from twaugh on 2011-10-12 10:10:15 EDT ---

It takes resources (memory, CPU) and for the common case it is simply not needed.

Out of interest, how are you logging into this machine?  I ask because GNOME connects to CUPS on login in any case in order to provide print job notifications...

--- Additional comment from alekcejk on 2011-10-12 10:19:37 EDT ---

I logging into KDE but I also have /etc/xdg/autostart/print-applet.desktop but looks like it is not used because of NotShowIn=GNOME;KDE;

--- Additional comment from twaugh on 2011-10-20 10:31:42 EDT ---

Re-opening because I think there is more going on here, involving colord.

--- Additional comment from twaugh on 2011-10-20 10:31:52 EDT ---

*** Bug 746935 has been marked as a duplicate of this bug. ***

--- Additional comment from twaugh on 2011-10-20 10:50:23 EDT ---

How to reproduce it:

systemctl stop cups.service
killall colord
time lpstat -s

--- Additional comment from twaugh on 2011-10-20 12:03:08 EDT ---

The problem is that gnome-settings-daemon connects to cupsd using the socket, which causes systemd to start cupsd.

cupsd registers its printers with colord, which causes dbus-daemon to start colord.

colord looks for devices, which causes libsane to start each SANE backend in discovery mode.

The hpaio backend connects to the CUPS socket to ask about configured printers...

and that's where it times out, because cupsd has not yet checked in with systemd to start receiving connections, because it is not yet ready to.

The solution is to modify hpaio so that it honours the localOnly flag.  When this flag is set (which it is when colord uses SANE), hpaio will not ask CUPS for its printers.

--- Additional comment from updates on 2011-10-20 12:04:18 EDT ---

hplip-3.11.10-5.fc16 has been submitted as an update for Fedora 16.
https://admin.fedoraproject.org/updates/FEDORA-2011-13765

--- Additional comment from updates on 2011-10-20 18:16:25 EDT ---

Package hplip-3.11.10-5.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 hplip-3.11.10-5.fc16'
as soon as you are able to.
Please go to the following url:
https://admin.fedoraproject.org/updates/FEDORA-2011-13765
then log in and leave karma (feedback).

--- Additional comment from updates on 2011-10-24 23:44:15 EDT ---

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

--- Additional comment from peter.weber on 2011-11-17 04:53:39 EST ---

https://bugzilla.redhat.com/show_bug.cgi?id=746935

I'm using network-printer with hplip on my fresh Fedora 16 installation and since I configured the printers the first login to the Gnome-Shell fails after a half minute with the message "Oh no. Something goes wrong...".

I used as work-around the tip from Tim Waugh

ln -s /lib/systemd/system/cups.service /etc/systemd/system/multi-user.target.wants/


That fixed it for me. The login to Fallback is not affected, maybe the internals of Gnome work here in an other way.
i.e.

* Everyone with network-printers (controlled by hplip?) is affected
* Gnome-Shell login succeed only on second attempt
* Gnome-Shell login is delayed through this, by approximately half minute
* Gnome-Shell doesn't show an error which gives "normal" users an real usuable hint, about what causes the problem


I want to ask to reopen the bug and rise the priority?

--- Additional comment from twaugh on 2011-11-17 06:33:09 EST ---

Peter: what does 'rpm -q libsane-hpaio' say?

It would also be useful to see debugging logs from the failed login attempt.  To do this, please modify /etc/rsyslog.conf so that this line:

*.info;mail.none;authpriv.none;cron.none                /var/log/messages

read like this:

*.debug;*.info;mail.none;authpriv.none;cron.none        /var/log/messages

(in other words, add "*.debug;" to the beginning of the line)

Now also do this:

su -c 'cupsctl --debug-logging'

After doing these things, please note the time and reboot.

After attempting to log in, and this failing, note the time again.  Now log in and attach the lines from /var/log/messages and /var/log/cups/error_log that occur between the two times you noted.

--- Additional comment from twaugh on 2012-01-23 07:27:46 EST ---

*ping*

--- Additional comment from udovdh on 2012-09-23 08:10:15 EDT ---

Can someone explain why I was sent here because the 'gnome-session: WARNING: Application 'gnome-settings-daemon.desktop' failed to register before timeout' bug was a duplicate?

--- Additional comment from udovdh on 2012-09-23 08:18:25 EDT ---

Over here the error was produced after logging out and in because of Xorg etc updates.
So cupsd was already running and remained running.
This is on Fedora 17, approximately one year after starting this bug.
I never saw this issue before.
Why is the interaction set up so that it appears to be a non-parallel proces?
Why can't my GUI start while things like printers sort out their daemon-mess? (did you count the number of components you mentioned related to cupsd?)
Why does  my gdm or whateevr think that my gui has failed while all gui components were fine?

- The starting conditions for triggering the 'gnome-session: WARNING: Application 'gnome-settings-daemon.desktop' failed to register before timeout' bug were different from Tim's explanation
- The jungle of stuff does not need to block the startup of my Xorg
- The startup of Xorg (gdm, whatever) should only think and mention the graphical session has failed when something is really wrong

--- Additional comment from udovdh on 2012-09-23 08:34:35 EDT ---

An extra logout/login did not trigger the phenomena.

--- Additional comment from twaugh on 2012-09-24 06:53:16 EDT ---

I think it's unlikely that you are seeing this particular bug, but instead some other component is being slow to start up.

Following the instructions from comment #23 should get the information about which component is being slow, because gdm should add messages about what it is doing to /var/log/messages as you log in.

--- Additional comment from udovdh on 2012-09-25 05:16:30 EDT ---

Tim, the causes for slow login might be different, but that still does not epxlain why the Xorg login process appears to be a linear process, no parallelism for less important tasks.
It cannot be that cups or whatever slows down the startup/login of my session into Xorg. Only stuff directly needed for my session should be waited for, the rest can be in parallel slower processes.
Also Xorg draws the wrong conclusion because of all this which should not happen.
The graphical side of the session was all OK. It needs to be more specific.

--- Additional comment from twaugh on 2012-09-27 08:00:45 EDT ---

udo: I think you need to file a separate bug report.

A graphical login session is more than simply Xorg, and some components (such as the settings daemon) are mandatory.  They should never fail, obviously, and it was an inadvertent design error -- since fixed, I believe -- that caused the original issue reported here.

I'm going to close this bug report. Please file a separate one.