cups/cups-browsed causing delay in shutdown (16.04)

Bug #1638986 reported by Lucas Liebenwein on 2016-11-03
26
This bug affects 3 people
Affects Status Importance Assigned to Milestone
cups-filters (Ubuntu)
Undecided
Unassigned
Xenial
Undecided
Unassigned

Bug Description

Description: Ubuntu 16.04.1 LTS
Release: 16.04

cups-filters:
  Installed: 1.8.3-2ubuntu3.1
  Candidate: 1.8.3-2ubuntu3.1
  Version table:
 *** 1.8.3-2ubuntu3.1 500
        500 http://us.archive.ubuntu.com/ubuntu xenial-updates/main amd64 Packages
        100 /var/lib/dpkg/status
     1.8.3-2ubuntu3 500
        500 http://us.archive.ubuntu.com/ubuntu xenial/main amd64 Packages

Bug description:

I have updated to the latest cups-filters version to fix the bug as described by bug report #1579905 but I still get that Ubuntu takes very long to shutdown.

For now, I have simply disabled cups-browser and I manually start it up every time I need to print something.

It is probably related to

https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=832637

as Till has described in #1579905. I tried to download and compile the upstream version at BZR as suggested for Debian but I ended up not being able to print anymore and instead went back to the current version in the package distribution.

Hopefully, there is an easy fix for Ubuntu 16.04 as well.

[Impact]

On many machines the shutdown will take unusually long, typically the 90-second timeout after which a hanging process gets killed. One case where this easily happens is if you have a remote CUPS server sharing printers which your local cups-browsed picks up and your local CUPS is not listening on localhost:631 (usually when it does not share printers). cups-browsed also tries to access the local cupsd on localhost:631 and hangs.

[Testcase]

Take two machines in one local network (can also be VMs), one being a CUPS server with at least one print queue being shared, another a client with CUPS and cups-browsed running but not sharing local queues and not listening on localhost:631. It picks up the server's queues but when trying to shut down cups-browsed, cups-browsed hangs. The fixed package (cups-filters 1.8.3-2ubuntu3.2) solves this problem as its cups-browsed shuts down correctly.

[Regression Potential]

The patch is not small, but it does only small and simple changes, not replacing big bunches of code by other big bunches of code, so the regression potential is rather low. The changes in the patch are also all backported from the working upstream code of cups-filters.

Changed in cups-filters (Ubuntu Xenial):
milestone: none → xenial-updates
status: New → In Progress
Changed in cups-filters (Ubuntu):
status: New → Fix Released
description: updated
Till Kamppeter (till-kamppeter) wrote :

Uploaded a fixed package to xenial-proposed. As soon as it gets approved instructions for testing it will get posted here. Please test it and report back here as your feedback is required for the package getting into the official updates for Xenial.

For the SRU team: debdiff attached.

Hello Lucas, or anyone else affected,

Accepted cups-filters into xenial-proposed. The package will build now and be available at https://launchpad.net/ubuntu/+source/cups-filters/1.8.3-2ubuntu3.2 in a few hours, and then in the -proposed repository.

Please help us by testing this new package. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation on how to enable and use -proposed.Your feedback will aid us getting this update out to other Ubuntu users.

If this package fixes the bug for you, please add a comment to this bug, mentioning the version of the package you tested, and change the tag from verification-needed to verification-done. If it does not fix the bug for you, please add a comment stating that, and change the tag to verification-failed. In either case, details of your testing will help us make a better decision.

Further information regarding the verification process can be found at https://wiki.ubuntu.com/QATeam/PerformingSRUVerification . Thank you in advance!

Changed in cups-filters (Ubuntu Xenial):
status: In Progress → Fix Committed
tags: added: verification-needed
Jan Gerrit (jg-burg-borgholz) wrote :

Hi,

I've tested cups-filters 1.8.3-2ubuntu3.2, but the problem (90 sec delay on shutdown) remains.

apt-cache policy cups-filters
cups-filters:
  Installiert: 1.8.3-2ubuntu3.2
  Installationskandidat: 1.8.3-2ubuntu3.2
  Versionstabelle:
 *** 1.8.3-2ubuntu3.2 500
        500 http://archive.ubuntu.com/ubuntu xenial-proposed/main amd64 Packages
        100 /var/lib/dpkg/status
     1.8.3-2ubuntu3.1 500
        500 http://ftp.hosteurope.de/mirror/archive.ubuntu.com/ubuntu xenial-updates/main amd64 Packages
     1.8.3-2ubuntu3 500
        500 http://ftp.hosteurope.de/mirror/archive.ubuntu.com/ubuntu xenial/main amd64 Packages

Greetings, Jan Gerrit

Lucas Liebenwein (lucaslie) wrote :

Hi,

thank you very much for the update. Unfortunately, it doesn't work for me either. I just tested it an hour ago.

cups-filters:
  Installed: 1.8.3-2ubuntu3.2
  Candidate: 1.8.3-2ubuntu3.2
  Version table:
 *** 1.8.3-2ubuntu3.2 500
        500 http://us.archive.ubuntu.com/ubuntu xenial-proposed/main amd64 Packages
        100 /var/lib/dpkg/status
     1.8.3-2ubuntu3.1 500
        500 http://us.archive.ubuntu.com/ubuntu xenial-updates/main amd64 Packages
     1.8.3-2ubuntu3 500
        500 http://us.archive.ubuntu.com/ubuntu xenial/main amd64 Packages

Please let me know if you need any more information.

Best,
Lucas

tags: added: verification-failed
removed: verification-needed
Till Kamppeter (till-kamppeter) wrote :

Everyone for whom the proposed package does not work, please attach the following files, one by one, not compressed, and not packaged together:

/etc/cups/cups-browsed.conf
/var/log/cups/cups-browsed_log
/var/log/cups/error_log
/lib/systemd/system/cups.service
/lib/systemd/system/cups-browsed.service

Did you restart CUPS at some point (while cups-browsed was still running)? For example via a "kill -HUP ..." or a "sudo systemctl restart cups"/"sudo systemctl reload cups"?

Please also post the output of "lpstat -v" with cups-browsed running and without cups-browsed running.

Lucas Liebenwein (lucaslie) wrote :

Hello,

please find attached the desired files. Unfortunately, there is no /var/log/cups/cups-browsed_log, but only a access_log. I attached this one instead in case it helps.

I never restarted cups, only the computer itself to test it.

Lucas Liebenwein (lucaslie) wrote :
Lucas Liebenwein (lucaslie) wrote :
Lucas Liebenwein (lucaslie) wrote :
Lucas Liebenwein (lucaslie) wrote :

Sorry for the spam. I couldn't figure out how to attach multiple files.

Lucas Liebenwein (lucaslie) wrote :

Sorry, cups-browsed did not have debug logging yet in 1.8.3. So there will be no /var/log/cups/cups-browsed_log.

To make cups-browsed logging, open a terminal and run the following commands:

cd
sudo systemctl stop cups-browsed
nohup sudo /usr/sbin/cups-browsed --debug > `pwd`/cups-browsed.log 2>&1 &

Reboot and after that attach the cups-browsed.log file here (should be in your home directory).

If the delay does not always happen, please attach a cups-browsed.log from a delayed shutdown and one from a shutdown where the delay did not happen.

Lucas Liebenwein (lucaslie) wrote :

Please find attached the the log file. Remember to start cups-browsed again via sudo systemctl start cups-browsed so that you are connected to the cups server once more.

The delayed shutdown always happens when I am connected to the network that has cups printers. When I am not connected to any cups server it is fine.

Jan Gerrit (jg-burg-borgholz) wrote :

Hi Till,

don't know why, but if I stop cups-browsed and restart it (with the commands below), all work fine.
~> sudo systemctl stop cups-browsed
~> nohup sudo /usr/sbin/cups-browsed --debug > `pwd`/cups-browsed.log 2>&1 &

If I restart it with
~> sudo systemctl stop cups-browsed
~> sudo systemctl start cups-browsed
I've the 90 seconds delay again.

I have uploaded a new version of this SRU now, cups-filters_1.8.3-2ubuntu3.3, in addition to the first version it contains an additional fix against delayed shutdown, namely not scheduling failed operations for repeating during shutdown.

In addition, I have added a patch for optional time-stamped debug logging into a file. Thia should help to find the cause of delayed shutdowns if this SRU still does not solve the problem.

So please test this version as soon as it gets available in xenial-proposed and appropriately announced here in this bug report. As always your feedback is required to make this an official update for everyone.

In the case that you still suffer the delayed shutdowns with this version, please add a line

DebugLogging file

to /etc/cups/cups-browsed.conf and restart cups-browsed via

sudo systemctl stop cups-browsed
sudo systemctl start cups-browsed

If you observe the delayed shutdown again in the future, please attach your /var/log/cups/cups-browsed.conf file to this bug report. Thanks.

tags: removed: verification-failed

Attached is the debdiff of all changes to fix this bug, including the first version of this SRU and the updated version.

Brian Murray (brian-murray) wrote :

Hello Lucas, or anyone else affected,

Accepted cups-filters into xenial-proposed. The package will build now and be available at https://launchpad.net/ubuntu/+source/cups-filters/1.8.3-2ubuntu3.3 in a few hours, and then in the -proposed repository.

Please help us by testing this new package. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation on how to enable and use -proposed.Your feedback will aid us getting this update out to other Ubuntu users.

If this package fixes the bug for you, please add a comment to this bug, mentioning the version of the package you tested, and change the tag from verification-needed to verification-done. If it does not fix the bug for you, please add a comment stating that, and change the tag to verification-failed. In either case, details of your testing will help us make a better decision.

Further information regarding the verification process can be found at https://wiki.ubuntu.com/QATeam/PerformingSRUVerification . Thank you in advance!

tags: added: verification-needed

As a part of the Stable Release Updates quality process a search for Launchpad bug reports using the version of cups-filters from xenial-proposed was performed and bug 1670436 was found. Please investigate this bug report to ensure that a regression will not be created by this SRU. In the event that this is not a regression remove the "verification-failed" tag from this bug report and add the tag "bot-stop-nagging" to bug 1670436 (not this bug). Thanks!

tags: added: verification-failed
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Duplicates of this bug

Other bug subscribers