Bug#852436: cups-browsed uses 100% CPU - SOLVED (patch attached)
Thank you very much for the patch.
I have applied it now to he upstream code of cups-filters (BZR rev. 7672).
Note that the error message
"Unable to create/modify CUPS queue (Success)!"
is actually caused by another bug which I had already fixed earlier. The
queue has actually been created but CUPS has returned a non-zero value.
In the beginning I assumed all non-zero values as errors, but CUPS has
some non-zero values which are not errors. In cups-filters 1.13.4 I have
fixed this and since then successfully created CUPS queue do not get
re-created repeatedly.
Till
On 08/09/2017 01:00 PM, Cédric Dufour - Idiap Research Institute wrote:
On 09/08/17 10:02, Cédric Dufour - Idiap Research Institute wrote:
I confirm this issue is still present is current Debian Stable/Stretch and
renders CUPS unusable in network printing environments.
I could backport the packages from testing or experimental, but then I would
miss the updates from the Debian Security team (and looking at the updates
history of CUPS filters/browsed in Debian OldStable/Jessie, it is not something
I'm looking forwards to)
I tracked down the issue to a timeout when 'cups-browsed' interacts with the local 'cups'
server ("cupsDoFileRequest" call).
The 'cups-browsed' hard-coded timeout for such operations is 3 seconds.
This timeout is the cause of the witnessed "Unable to create/modify CUPS queue
(Success)!" error messages (and 'cups-browsed' looping infinitely in attempts to add
the failing printers/queues)
For large (fancy ?) PPDs, the local 'cups' server can take up to 8 (!) seconds
to process the addition of a remote printer queue based on the PPD retrieved
from the (BrowsePoll-ed) server (as witnessed on a 3.4GHz Intel I7-2600K test
host, during wich one CPU core is stuck at 100%).
The attached patch file - for cups-filters 1.11.6 (Debian/Stretch) - allows one to configure the
timeouts of both local and remote 'cups-browsed' HTTP connections, thanks to the new
"HttpLocalTimeout" and "HttpRemoteTimeout" configuration settings. Setting the
former to 10 seconds fixed the issue with my troublesome PPDs/printers (INEO+ copiers).
Please note that this issue will still be present in 'cups-browsed' 1.16.0
along 'cups' 2.2.4, as backported from Testing and *verified* on Stretch.
(it should not be difficult to forward-port the attached patch, however)
I hope this patch can meet your approval for its addition in Debian patches
series and considered even for current Stable release (knowing that enterprise
environments with big printing beasts will be bound to stumble on the same
problem).
And do you have a privileged contact to propose this patch be included upstream
?
Best,
Cédric
Bug#852436: cups-browsed uses 100% CPU - SOLVED (patch attached)
On 09/08/17 10:02, Cédric Dufour - Idiap Research Institute wrote:
> I confirm this issue is still present is current Debian Stable/Stretch and
> renders CUPS unusable in network printing environments.
> I could backport the packages from testing or experimental, but then I would
> miss the updates from the Debian Security team (and looking at the updates
> history of CUPS filters/browsed in Debian OldStable/Jessie, it is not
> something I'm looking forwards to)
I tracked down the issue to a timeout when 'cups-browsed' interacts with the
local 'cups' server ("cupsDoFileRequest" call).
The 'cups-browsed' hard-coded timeout for such operations is 3 seconds.
This timeout is the cause of the witnessed "Unable to create/modify CUPS queue
(Success)!" error messages (and 'cups-browsed' looping infinitely in attempts
to add the failing printers/queues)
For large (fancy ?) PPDs, the local 'cups' server can take up to 8 (!) seconds
to process the addition of a remote printer queue based on the PPD retrieved
from the (BrowsePoll-ed) server (as witnessed on a 3.4GHz Intel I7-2600K test
host, during wich one CPU core is stuck at 100%).
The attached patch file - for cups-filters 1.11.6 (Debian/Stretch) - allows one
to configure the timeouts of both local and remote 'cups-browsed' HTTP
connections, thanks to the new "HttpLocalTimeout" and "HttpRemoteTimeout"
configuration settings. Setting the former to 10 seconds fixed the issue with
my troublesome PPDs/printers (INEO+ copiers).
Please note that this issue will still be present in 'cups-browsed' 1.16.0
along 'cups' 2.2.4, as backported from Testing and *verified* on Stretch.
(it should not be difficult to forward-port the attached patch, however)
I hope this patch can meet your approval for its addition in Debian patches
series and considered even for current Stable release (knowing that enterprise
environments with big printing beasts will be bound to stumble on the same
problem).
And do you have a privileged contact to propose this patch be included upstream
?
Best,
Cédric
diff -urN cups-filters-1.11.6.orig/utils/cups-browsed.c cups-filters-1.11.6/utils/cups-browsed.c
--- cups-filters-1.11.6.orig/utils/cups-browsed.c 2017-08-09 16:48:36.0 +0200
+++ cups-filters-1.11.6/utils/cups-browsed.c 2017-08-09 17:01:05.609442696 +0200
@@ -339,6 +339,8 @@
static guint update_netifs_sourceid = 0;
static char local_server_str[1024];
static char *DomainSocket = NULL;
+static unsigned int HttpLocalTimeout = 5;
+static unsigned int HttpRemoteTimeout = 10;
static ip_based_uris_t IPBasedDeviceURIs = IP_BASED_URIS_NO;
static unsigned int CreateRemoteRawPrinterQueues = 0;
static unsigned int CreateIPPPrinterQueues = 0;
@@ -579,6 +581,7 @@
int
http_timeout_cb(http_t *http, void *user_data)
{
+ debug_printf("HTTP timeout! (consider increasing HttpLocalTimeout/HttpRemoteTimeout value)\n");
return 0;
}
@@ -591,7 +594,7 @@
cupsEncryption());
}
if (local_conn)
-httpSetTimeout(local_conn, 3, http_timeout_cb, NULL);
+httpSetTimeout(local_conn, HttpLocalTimeout, http_timeout_cb, NULL);
else
debug_printf("cups-browsed: Failed creating http connection to local CUPS daemon: %s:%d\n", cupsServer(), ippPort());
@@ -2617,7 +2620,7 @@
p->port);
if (http) {
/* Check whether the printer is idle, processing, or disabled */
- httpSetTimeout(http, 2, http_timeout_cb, NULL);
+ httpSetTimeout(http, HttpRemoteTimeout, http_timeout_cb, NULL);
request = ippNewRequest(CUPS_GET_PRINTERS);
ippAddStrings(request, IPP_TAG_OPERATION, IPP_TAG_KEYWORD,
"requested-attributes",
@@ -3576,7 +3579,7 @@
p->timeout = current_time + TIMEOUT_RETRY;
break;
}
- httpSetTimeout(http, 3, http_timeout_cb, NULL);
+ httpSetTimeout(http, HttpLocalTimeout, http_timeout_cb, NULL);
/* Do not auto-save option settings due to the print queue creation
process */
@@ -3629,7 +3632,7 @@
p->no_autosave = 0;
break;
}
- httpSetTimeout(remote_http, 3, http_timeout_cb, NULL);
+ httpSetTimeout(remote_http, HttpRemoteTimeout, http_timeout_cb, NULL);
if ((loadedppd = cupsGetPPD2(remote_http, p->name)) == NULL &&
CreateRemoteRawPrinterQueues == 0) {
debug_printf("Unable to load PPD file for %s from the server %s:%d!\n",
@@ -5631,7 +5634,7 @@
return;
}
- httpSetTimeout(conn, 3, http_timeout_cb, NULL);
+ httpSetTimeout(conn, HttpRemoteTimeout, http_timeout_cb, NULL);
debug_printf ("cups-browsed [BrowsePoll %s:%d]: IPP-Cancel-Subscription\n",
context->server, context->port);
@@ -5772,7 +5775,7 @@
goto fail;
}
- httpSetTimeout(conn, 3, http_timeout_cb, NULL);
+ httpSetTimeout(conn, HttpRemoteTimeout, http_timeout_cb, NULL);
if (context->can_subscribe) {
if (context->subscription_id == -1) {
@@ -6288,6 +6291,19 @@
} else if (!strcasecmp(line, "DomainSocket") && value) {
if (value[0] != '\0')
DomainSocket = strd
Bug#852436: cups-browsed uses 100% CPU (Stretch)
Hello, I confirm this issue is still present is current Debian Stable/Stretch and renders CUPS unusable in network printing environments. I could backport the packages from testing or experimental, but then I would miss the updates from the Debian Security team (and looking at the updates history of CUPS filters/browsed in Debian OldStable/Jessie, it is not something I'm looking forwards to) Can we hope in seeing this issue also fixed in Debian Stable/Stretch ? Thanks for your efforts, Cédric -- Cédric Dufour @ Idiap Research Institute
Bug#852436: cups-browsed uses 100% CPU
Unfortunately I've to report the bug's still persistent on my machine. However, I was able to track it down a bit byte more: The CPU jolt seems to be somehow linked to the computer's connection to the wired network. I've been on the road the last couple of weeks using the computer in wireless mode only without any problem. But when returning to university and connecting the computer to the ethernet cable the previously reported behaviour of 100% CPU workload appears again. Please let me know if there's anything I can do or infos to be provided to narrow this further down. many thanks Olsen On 25/01/17 06:40, Didier 'OdyX' Raboud wrote: > Control: tags -1 +patch +moreinfo > > olsen, > > This would be the package built with Till's patch included: > > > https://people.debian.org/~odyx/tmp/eiRa3quooCai4ju0/cups-browsed_1.11.6-4~test852436_amd64.deb > > Can you test and confirm that it fixes that bug for you? > > Cheers, > signature.asc Description: OpenPGP digital signature
Bug#852436: cups-browsed uses 100% CPU
Control: tags -1 +patch +moreinfo olsen, This would be the package built with Till's patch included: https://people.debian.org/~odyx/tmp/eiRa3quooCai4ju0/cups-browsed_1.11.6-4~test852436_amd64.deb Can you test and confirm that it fixes that bug for you? Cheers, -- OdyX signature.asc Description: This is a digitally signed message part.
Bug#852436: cups-browsed uses 100% CPU
Thank you for the log file. The high load was probably caused by cups-browsed repeatedly creating local queues for the discovered remote queues as it did not recognize that the queues were already successfully generated. I have corrected the error checking now to interpret the resulting IPP status codes correctly as success or error. This I have done on the upstream BZR repository, rev. 7601. The lines in the log file leading to this assumptions are: Tue Jan 24 14:49:52 2017 Unable to create/modify CUPS queue (Success)! which appear several times. cups-browsed considered the operation having errored, therefore outputting this line. In the parantheses the last error string of the operating system is inserted, which is "Success" meaning that the system did not see any error here. Till
Bug#852436: cups-browsed uses 100% CPU
Please attach your /etc/cups/cups-browsed.conf and the output of the command lpstat -v Also activate debug logging by adding the line DebugLogging file to /etc/cups/cups-browsed.conf and restart cups-browsed via sudo systemctl stop cups-browsed sudo systemctl start cups-browsed When cups-browsed takes 100% CPU the next time, kill cups-browsed again and reply to this bug report attaching the /var/log/cups/cups-browsed_log file. tell at which date and time you observed the 100% CPU so that we can find the relevant part o the log file. Till
Bug#852436: cups-browsed uses 100% CPU
Package: cups-browsed Version: 1.11.6-2 Severity: normal Dear Maintainer, Since my last upgrade cups-browsed uses up 100% of a CPU and becomes unusable. I've to kill it to prevent the computer to panic. Wonder if the modified version of cups-browsed.conf is the fly in the ointment. However I haven't change that file for that last year or so and it was running fine. -- System Information: Debian Release: 9.0 APT prefers testing APT policy: (500, 'testing') Architecture: amd64 (x86_64) Foreign Architectures: i386 Kernel: Linux 4.8.0-2-amd64 (SMP w/4 CPU cores) Locale: LANG=en_GB.UTF-8, LC_CTYPE=en_GB.UTF-8 (charmap=UTF-8) Shell: /bin/sh linked to /bin/dash Init: systemd (via /run/systemd/system) Versions of packages cups-browsed depends on: ii cups-daemon 2.2.1-4 ii init-system-helpers 1.46 ii libavahi-client3 0.6.32-1 ii libavahi-common3 0.6.32-1 ii libavahi-glib1 0.6.32-1 ii libc62.24-8 ii libcups2 2.2.1-4 ii libglib2.0-0 2.50.2-2 ii libldap-2.4-22.4.44+dfsg-2 ii lsb-base 9.20161125 Versions of packages cups-browsed recommends: ii avahi-daemon 0.6.32-1 cups-browsed suggests no packages. -- Configuration Files: /etc/cups/cups-browsed.conf changed: BrowseRemoteProtocols dnssd cups -- no debconf information
