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'
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'?
cupsd not running before first run 'lpstat -s' so how can I know PID of cupsd for strace?
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.
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.
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'.
But still don't know how to do this when cupsd not started.
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
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
I think I see what's going on. Could you please attach the output of 'systemctl show printer.target'?
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
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
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)?
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...
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;
Re-opening because I think there is more going on here, involving colord.
*** Bug 746935 has been marked as a duplicate of this bug. ***
How to reproduce it: systemctl stop cups.service killall colord time lpstat -s
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.
hplip-3.11.10-5.fc16 has been submitted as an update for Fedora 16. https://admin.fedoraproject.org/updates/FEDORA-2011-13765
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).
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.
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?
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.
*ping*
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?
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
An extra logout/login did not trigger the phenomena.
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.
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.
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.