Bug 1044602 - Long wait at shutdown/reboot
Summary: Long wait at shutdown/reboot
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Fedora
Classification: Fedora
Component: cups
Version: 20
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
Assignee: Tim Waugh
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard: https://fedoraproject.org/wiki/Common...
Depends On: 1023820
Blocks:
TreeView+ depends on / blocked
 
Reported: 2013-12-18 16:20 UTC by antonio montagnani
Modified: 2014-01-05 06:06 UTC (History)
16 users (show)

Fixed In Version: cups-1.7.0-9.fc20
Clone Of:
Environment:
Last Closed: 2014-01-05 06:06:35 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)
from systemadm (76.05 KB, image/png)
2013-12-18 16:41 UTC, antonio montagnani
no flags Details
extract of messages (690 bytes, text/plain)
2013-12-19 13:44 UTC, antonio montagnani
no flags Details

Description antonio montagnani 2013-12-18 16:20:28 UTC
Description of problem:
wait long during shutdown/reboot

Version-Release number of selected component (if applicable):
systemd-208-9.fc20.x86_64

How reproducible:
always

Steps to Reproduce:
1.Shutdown/Reboot
2.sit and wait 
3.

Actual results:
if I  go in text mode during shutdown I see a message
a stop job is running for User Manager for 42
or a similar message related for CUPS service

Expected results:
smooth shutdown/reboot

Additional info:
I see for example strange messages in systemadm (whenever it doesn'freeze) related to CUPS.service connected to shutdown.target that is dead!!!

Comment 1 antonio montagnani 2013-12-18 16:37:03 UTC
the message usually is:

a stop job is running for Cups Printing service and in front of it I have red asterisks until it completes shutdown

Comment 2 antonio montagnani 2013-12-18 16:41:29 UTC
Created attachment 838435 [details]
from systemadm

I don't know if it can help to debug but I see some conflicts

Comment 3 antonio montagnani 2013-12-18 17:00:24 UTC
It was working fine on F-19 (forgot to mention) and problem persists also when I use kernel from F-19, therefore I assume that is connected to systemd

Comment 4 Chris Murphy 2013-12-18 20:33:22 UTC
Different service unit, but could be the same underlying cause as in bug 1023820.

Comment 5 antonio montagnani 2013-12-19 13:44:22 UTC
Created attachment 838987 [details]
extract of messages

this is the part of var/log/messages when shutdown freezes for a while

Comment 6 Zbigniew Jędrzejewski-Szmek 2013-12-19 21:29:31 UTC
I don't think this is the same as bug 1023820, or at least the cups.service part isn't. Does starting and stopping cups normally work (systemctl start cups, systemctl stop cups)? If you see the timeout here too, then probably it's a cups issue.

Comment 7 antonio montagnani 2013-12-19 21:52:27 UTC
it takes a long time to stop cups and I get:

systemctl stop cups
Warning: Stopping cups, but it can still be activated by:
  cups.path
  cups.socket

Shall I change the component to blame??

Comment 8 antonio montagnani 2013-12-21 09:12:15 UTC
the shutdown time seems normal if given when seesion is terminated, much longer if issued from inside a session

Comment 9 Robert Hancock 2013-12-22 23:50:56 UTC
I am also seeing cups hang on shutdown. It hangs when stopping it manually from the command line as well. The stack trace from running pstack on the cupsd process shows it seems to be locking a mutex in Avahi. 

#0  0x00007f3cf994f060 in __pause_nocancel () from /lib64/libpthread.so.0
#1  0x00007f3cf9945c95 in __pthread_mutex_lock_full () from /lib64/libpthread.so.0
#2  0x00007f3cfa95514c in avahi_threaded_poll_stop () from /lib64/libavahi-common.so.3
#3  0x00007f3cfc08173e in cupsdStopBrowsing ()
#4  0x00007f3cfc09dc25 in cupsdStopServer ()
#5  0x00007f3cfc06be94 in main ()

It seems like this bug is still assigned to the systemd email address, even though it's assigned to cups component and seems to have nothing to do with systemd. Can someone change the owner?

Comment 10 Robert Hancock 2013-12-24 04:27:37 UTC
This problem is completely reproducible 100% of the time on my system. cupsd never exits when receiving SIGTERM. This is the strace output from sending SIGTERM to cupsd:

epoll_wait(4, 7f2463f4e680, 4096, 3125000) = -1 EINTR (Interrupted system call)
--- SIGTERM {si_signo=SIGTERM, si_code=SI_USER, si_pid=18030, si_uid=0} ---
rt_sigreturn()                          = -1 EINTR (Interrupted system call)
epoll_ctl(4, EPOLL_CTL_DEL, 9, {0, {u32=0, u64=7206739137372618752}}) = 0
epoll_ctl(4, EPOLL_CTL_DEL, 10, {0, {u32=0, u64=7206739137372618752}}) = 0
epoll_ctl(4, EPOLL_CTL_DEL, 11, {0, {u32=0, u64=7206739137372618752}}) = 0
close(9)                                = 0
close(10)                               = 0
close(11)                               = 0
unlink("/var/run/cups/cups.sock")       = 0
sendmsg(12, {msg_name(0)=NULL, msg_iov(2)=[{"l\1\0\1\0\0\0\0\24\0\0\0}\0\0\0\1\1o\0\25\0\0\0/Client1"..., 144}, {"", 0}], msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 144
poll([{fd=12, events=POLLIN}], 1, 25000) = 1 ([{fd=12, revents=POLLIN}])
recvmsg(12, {msg_name(0)=NULL, msg_iov(1)=[{"l\2\1\1\0\0\0\0\304\0\0\0%\0\0\0\6\1s\0\6\0\0\0:1.549\0\0"..., 2048}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_CMSG_CLOEXEC) = 56
recvmsg(12, 0x7fffcbe46690, MSG_CMSG_CLOEXEC) = -1 EAGAIN (Resource temporarily unavailable)
futex(0x7f2464036a00, FUTEX_LOCK_PI, 1) = -1 ESRCH (No such process)
pause(

From what I can tell, the code path where the futex call inside of pthread_mutex_lock_full returns ESRCH indicates a non-robust PI mutex whose owner has died (or maybe there was no valid owner in the first place). Thus, glibc dutifully calls pause() and causes the process to hang up indefinitely.

I suspect that cups is using the Avahi API improperly. There is a patch in the cups SRPM called cups-avahi-no-threaded.patch which seems to be trying to avoid using the threaded versions of the Avahi methods, but this call to avahi_threaded_poll_stop is not removed by this patch. I am guessing this is some kind of oversight and that it should not be using this particular call.

A workaround for now is to add KillSignal=SIGKILL to /lib/systemd/system/cups.service so that systemd just nukes cupsd off with SIGKILL rather than trying to kill it nicely with SIGTERM. Obviously this is not ideal though.

The reporter (or someone with access) may want to add the CommonBugs keyword as this seems likely to impact many users.

Comment 11 Chris Murphy 2013-12-24 04:35:05 UTC
I wonder if this is related, but the stack trace doesn't match up with yours.

https://bugs.launchpad.net/ubuntu/+source/avahi/+bug/1131854
http://lists.linuxfoundation.org/pipermail/printing-architecture/2013/002820.html

But if so, it looks like an Avahi bug.

Comment 12 Robert Hancock 2013-12-24 04:42:56 UTC
I don't think that bug report is very similar to this one, other than both relating to problems with Avahi support in CUPS. It seems at this point that this particular problems is on the CUPS side.

Comment 13 Robert Hancock 2013-12-25 00:48:21 UTC
This may have been due to some non-default or outdated CUPS configuration. The /etc/cups/cupsd.conf file I had contained:

Port 631
BrowseOrder allow,deny
BrowseAllow all
BrowseRemoteProtocols CUPS
BrowseAddress @LOCAL
BrowseLocalProtocols CUPS dnssd
Allow @LOCAL

The default file contained in the F20 RPM contained:

Listen localhost:631
BrowseLocalProtocols dnssd

Restoring the default config file somehow fixes the hang on cupsd shutdown. It seems like there is still a bug being exposed here, though.

Comment 14 Robert Hancock 2013-12-25 01:30:15 UTC
Hmm.. apparently with the default setting of cups to not share local printers, the hang on shutdown doesn't occur. But if you enable "Publish shared printers connected to this system" in Print Settings - Server Settings, then it does. I guess that would make sense as whatever portion of the Avahi code is hanging likely isn't activated if printer sharing is disabled.

Comment 15 Robert Hancock 2013-12-30 03:53:40 UTC
Here's a stab at some text for Common Bugs for this:

CommonBugs title: CUPS daemon causes long pause on shutdown or reboot when printer sharing is enabled

CommonBugs summary: If the "Publish shared printers connected to this system" option is enabled in Print Settings - Server Settings, then the CUPS daemon will hang when the system tries to stop it (i.e. on shutdown/reboot or when stopping it manually with "systemctl stop cups.service"). After a few minutes, systemd will time out and forcibly kill the process allowing the shutdown/reboot to complete.

Known workarounds: Adding KillSignal=SIGKILL to /lib/systemd/system/cups.service will cause cupsd to be forcibly killed by systemd without attempting to shut it down cleanly. However, this could possibly result in adverse effects if the cups daemon is busy at the time of the shutdown. Alternately, disabling printer sharing appears to avoid the hang.

Comment 16 Adam Williamson 2013-12-30 06:10:40 UTC
Excellent text, Robert, many thanks. Added to CommonBugs with minimal changes. One note: systemd has a rather neat approach to configuration. You are not supposed to edit unit files in /usr/lib/systemd directly - they are not considered config files and will be overwritten on update of the containing package. What you are supposed to do is copy the unit to /etc/systemd/system and modify the copy. systemd will load unit files in /etc/systemd in preference to ones in /usr/lib/systemd when identically named units exist in both places. This neatly separates the distribution-owned 'stock' configuration from any 'local admin' configuration and avoids the mess of .rpmnew / .rpmsave files. It's a design that's used in a lot of Lennart-y stuff now and is starting to be picked up outside of the PoetteringVerse, so keep an eye out for it :)

Comment 17 Robert Hancock 2013-12-30 07:51:41 UTC
Yeah, I was aware of that. It is a bit cleaner - though in this case, the fact that the changes in the /usr/lib/systemd directory will get overwritten on the next update may be an advantage, assuming this bug gets fixed on the next update, as then this workaround will get taken out as well.

Comment 18 Tim Waugh 2014-01-02 17:35:21 UTC
Hopefully cups-1.7.0-9.fc20 fixes it. It removes the call to avahi_threaded_poll_stop() you noticed.

Comment 19 Andriy 2014-01-02 23:58:10 UTC
I removed cups package (cupsd, cups.service etc.) several weeks ago and nevertheless from time to time have to wait long during shutdown/reboot. I think, that in my case (as Chris wrote in Comment 4) the bug 1023820 is responsible for that.

Comment 20 Robert Hancock 2014-01-03 00:51:07 UTC
cups 1.7.0-9 build seems to resolve the hang on shutdown.

I updated with the build from Koji using:

yum update http://kojipkgs.fedoraproject.org//packages/cups/1.7.0/9.fc20/x86_64/cups-1.7.0-9.fc20.x86_64.rpm http://kojipkgs.fedoraproject.org//packages/cups/1.7.0/9.fc20/x86_64/cups-libs-1.7.0-9.fc20.x86_64.rpm http://kojipkgs.fedoraproject.org//packages/cups/1.7.0/9.fc20/noarch/cups-filesystem-1.7.0-9.fc20.noarch.rpm http://kojipkgs.fedoraproject.org//packages/cups/1.7.0/9.fc20/i686/cups-libs-1.7.0-9.fc20.i686.rpm

(Though, funnily enough, since the cups update process restarts the cups daemon, the update process hangs for a while since the stop of the old version of the daemon has to time out and kill the process..)

Comment 21 Sergio Basto 2014-01-03 03:31:14 UTC
(In reply to Robert Hancock from comment #20)
> cups 1.7.0-9 build seems to resolve the hang on shutdown.
> 
> I updated with the build from Koji using:
> 
> yum update
> http://kojipkgs.fedoraproject.org//packages/cups/1.7.0/9.fc20/x86_64/cups-1.
> 7.0-9.fc20.x86_64.rpm
> http://kojipkgs.fedoraproject.org//packages/cups/1.7.0/9.fc20/x86_64/cups-
> libs-1.7.0-9.fc20.x86_64.rpm
> http://kojipkgs.fedoraproject.org//packages/cups/1.7.0/9.fc20/noarch/cups-
> filesystem-1.7.0-9.fc20.noarch.rpm
> http://kojipkgs.fedoraproject.org//packages/cups/1.7.0/9.fc20/i686/cups-libs-
> 1.7.0-9.fc20.i686.rpm
> 
> (Though, funnily enough, since the cups update process restarts the cups
> daemon, the update process hangs for a while since the stop of the old
> version of the daemon has to time out and kill the process..)

same here , fix cups hangs on shutdown for a minute .
cups 1.7.0-9, IMO, should be submit for stable asap!

Comment 22 Fedora Update System 2014-01-03 10:24:08 UTC
cups-1.7.0-9.fc20 has been submitted as an update for Fedora 20.
https://admin.fedoraproject.org/updates/cups-1.7.0-9.fc20

Comment 23 Fedora Update System 2014-01-03 23:26:08 UTC
Package cups-1.7.0-9.fc20:
* should fix your issue,
* was pushed to the Fedora 20 testing repository,
* should be available at your local mirror within two days.
Update it with:
# su -c 'yum update --enablerepo=updates-testing cups-1.7.0-9.fc20'
as soon as you are able to.
Please go to the following url:
https://admin.fedoraproject.org/updates/FEDORA-2014-0151/cups-1.7.0-9.fc20
then log in and leave karma (feedback).

Comment 24 Fedora Update System 2014-01-05 06:06:35 UTC
cups-1.7.0-9.fc20 has been pushed to the Fedora 20 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.