Bug#841028: cups-daemon: cupsd uses 100% CPU

[Kim Brodowski]

Dear Maintainer,

we're experiencing very similar behaviour on our end and cups-filters > 1.13 
does not appear to fix the issue for us. For testing purposes we upgraded the 
packages on our Stretch server to their Buster counterparts:

We're currently running:
cups2.2.1-8+deb9u1
cups-bsd2.2.1-8+deb9u1
cups-client 2.2.1-8+deb9u1
cups-common 2.2.1-8+deb9u1
cups-core-drivers   2.2.1-8+deb9u1
cups-daemon 2.2.1-8+deb9u1
cups-filters1.20.3-1+b1
cups-filters-core-drivers   1.20.3-1+b1
cups-ipp-utils  2.2.1-8+deb9u1
cups-pdf2.6.1-22
cups-ppdc   2.2.1-8+deb9u1
cups-server-common  2.2.1-8+deb9u1
cupsddk 1.5.3-5+deb7u6

The cupsd process remains at 100% CPU usage.

strace (scrolling through rapidly):
poll([{fd=19, events=POLLIN}], 1, 0)= 1 ([{fd=19, revents=POLLIN}])
recv(21, "\247", 1, MSG_PEEK)   = 1
poll([{fd=21, events=POLLIN}], 1, 0)= 1 ([{fd=21, revents=POLLIN}])
epoll_wait(5, [{EPOLLIN, {u32=1468342600, u64=83072721224}}, {EPOLLIN, 
{u32=1468196936, u64=91662510152}}], 4096, 1000) = 2
recv(19, "\303", 1, MSG_PEEK)   = 1
poll([{fd=19, events=POLLIN}], 1, 0)= 1 ([{fd=19, revents=POLLIN}])
recv(21, "\247", 1, MSG_PEEK)   = 1
poll([{fd=21, events=POLLIN}], 1, 0)= 1 ([{fd=21, revents=POLLIN}])
epoll_wait(5, [{EPOLLIN, {u32=1468342600, u64=83072721224}}, {EPOLLIN, 
{u32=1468196936, u64=91662510152}}], 4096, 1000) = 2

The file descriptors correspond to the following sockets:
cupsd 32123   root   19u IPv4   33857634   
0t0TCP iserv.dev2.iserv.eu:ipp->Dogmeat.dev2.iserv.eu:43696 (CLOSE_WAIT)
cupsd 32123   root   21u IPv4   33865820   
0t0TCP iserv.dev2.iserv.eu:ipp->Dogmeat.dev2.iserv.eu:43706 (CLOSE_WAIT)

tshark doesn't show any network traffic on these sockets.

Bug#841028: cups-daemon: cupsd uses 100% CPU

[Brian Potkin]

On Thu 08 Jun 2017 at 00:01:55 +0200, Samuel Wolf wrote:

> 2017-06-07 23:47 GMT+02:00 Till Kamppeter :
> 
> > The fix prevents the repeated loading of this printer as it considers the
> > loading done after the first load.
> >
> >
> Is this update/patch for Stretch available?

Not yet.

cups-filters, cups-filters-core-drivers and libcupsfilters1 from
experimental will install on Stretch at the present time.

-- 
Brian.

Bug#841028: cups-daemon: cupsd uses 100% CPU

[Samuel Wolf]

2017-06-07 23:47 GMT+02:00 Till Kamppeter :

> The fix prevents the repeated loading of this printer as it considers the
> loading done after the first load.
>
>
Is this update/patch for Stretch available?


>Till
>
>

Bug#841028: cups-daemon: cupsd uses 100% CPU

[Till Kamppeter]

The fix prevents the repeated loading of this printer as it considers 
the loading done after the first load.


   Till

Bug#841028: cups-daemon: cupsd uses 100% CPU

[Samuel Wolf]

Hi Till,

2017-06-07 20:20 GMT+02:00 Till Kamppeter :

> On 06/07/2017 03:05 PM, Samuel Wolf wrote:
>
>> Wed Jun  7 20:03:07 2017 Unable to create/modify CUPS queue (Success)!
>>
>
> Here a successful operation was considered an error and this leads to the
> repetition.
>
> I have fixed this already in the 1.13.4 release of cups-filters.
>

this fix also the issue with the 100% CPU load and cups-browsed?
The load coming from the reload of the printers, right?

cups-filters:
  Installiert:   1.11.6-3
  Installationskandidat: 1.11.6-3
  Versionstabelle:
 *** 1.11.6-3 500
500 http://ftp.de.debian.org/debian stretch/main amd64 Packages
100 /var/lib/dpkg/status

No update for Stretch available.

Samuel


>
>Till
>
>

Bug#841028: cups-daemon: cupsd uses 100% CPU

[Till Kamppeter]

On 06/07/2017 03:05 PM, Samuel Wolf wrote:

Wed Jun  7 20:03:07 2017 Unable to create/modify CUPS queue (Success)!


Here a successful operation was considered an error and this leads to 
the repetition.


I have fixed this already in the 1.13.4 release of cups-filters.

   Till

Bug#841028: cups-daemon: cupsd uses 100% CPU

[Samuel Wolf]

Ok going a bit deeper in, I enable the debug logging file in
cups_browsed.conf and see that CUPS repeatedly reload some printers.

As soon I stop CUPS on the Debian Jessie server, the Debian Stretch client
CUPS stop using 100% CPU.

I have one printer two times on the Jessie CUPS server, but with different
default settings (color/black) and it look like cups-browsed load this
printers repeatedly.

[...]
Wed Jun  7 20:03:04 2017 Print queue Vertrieb is for remote CUPS queue(s)
and we get notifications from CUPS, using implicit class device URI
implicitclass:Vertrieb
Wed Jun  7 20:03:04 2017 Loaded PPD file /tmp/00a82593d31eb for printer
Vertrieb from server server1:631!
Wed Jun  7 20:03:04 2017 Editing PPD file /tmp/00a82593d31eb for printer
Vertrieb, setting the option defaults of the previous cups-browsed session
and inhibiting client-side filtering of the job, saving the resulting PPD
in /tmp/00a82593d9516.
Wed Jun  7 20:03:04 2017 Non-raw queue Vertrieb with PPD file:
/tmp/00a82593d9516
Wed Jun  7 20:03:07 2017 Unable to create/modify CUPS queue (Success)!
Wed Jun  7 20:03:07 2017 Creating/Updating CUPS queue for Vertrieb_Farbe
Wed Jun  7 20:03:07 2017 Queue has 0 duplicates
[...]

Bug#841028: cups-daemon: cupsd uses 100% CPU

[Samuel Wolf]

Same here on a fresh installed Debian Stretch.

Set only..
BrowsePoll server1
..in cups-browsed.conf and CUPS uses 100% CPU.

Bug#841028: cups-daemon: cupsd uses 100% CPU

[Peter Chubb]

Package: cups-daemon
Version: 2.2.1-1
Severity: important

Dear Maintainer,

Recently cupsd has started to use 100% CPU most of the time.
  PID USER  PR  NIVIRTRESSHR S  %CPU %MEM TIME+ COMMAND
20471 root  20   0  109684  31140   6232 R 100.0  0.2   9:49.86
  cupsd
  
stracing the process it looks as if it's continuously polling the
available printers.

All my (approx 50) printers are network connected via another CUPS
server (version 1.4.4) over which I have no control.

cups-browsed is installed, and has

  BrowseRemoteProtocols dnssd cups
  BrowsePoll remote-cups-server-address:631

in it.  All other settings are the defaults.

strace output -- this scrolls almost continuously:
write(6, "W [17/Oct/2016:08:32:26 +1100] C"..., 147) = 147
sendmsg(8, {msg_name=NULL, msg_namelen=0, 
msg_iov=[{iov_base="l\1\0\1\231\0\0\0005\3\0\0\235\0\0\0\1\1o\0\35\0\0\0/org/fre"...,
 iov_len=176}, {iov_base="\24\0\0\0blockhouse-p1-CMYK..\0\0\0\0\4\0\0\0"..., 
iov_len=153}], msg_iovlen=2, msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 329
poll([{fd=8, events=POLLIN}], 1, 5000)  = 1 ([{fd=8, revents=POLLIN}])
recvmsg(8, {msg_name=NULL, msg_namelen=0, 
msg_iov=[{iov_base="l\3\1\0015\0\0\0\30\f\0\0f\0\0\0\10\1g\0\1s\0\0\4\1s\0*\0\0\0"...,
 iov_len=2048}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, 
MSG_CMSG_CLOEXEC) = 173
recvmsg(8, {msg_namelen=0}, MSG_CMSG_CLOEXEC) = -1 EAGAIN (Resource temporarily 
unavailable)
socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 20
connect(20, {sa_family=AF_UNIX, sun_path="/var/run/nscd/socket"}, 110) = 0
sendto(20, "\2\0\0\0\2\0\0\0\4\0\0\0adm\0", 16, MSG_NOSIGNAL, NULL, 0) = 16
poll([{fd=20, events=POLLIN|POLLERR|POLLHUP}], 1, 5000) = 1 ([{fd=20, 
revents=POLLIN|POLLHUP}])
read(20, "\2\0\0\0\1\0\0\0\4\0\0\0\2\0\0\0\4\0\0\0\0\0\0\0", 24) = 24
read(20, "adm\0x\0", 6) = 6
close(20)   = 0
write(6, "W [17/Oct/2016:08:32:26 +1100] C"..., 147) = 147
sendmsg(8, {msg_name=NULL, msg_namelen=0, 
msg_iov=[{iov_base="l\1\0\0010\1\0\0006\3\0\0\235\0\0\0\1\1o\0\35\0\0\0/org/fre"...,
 iov_len=176}, {iov_base="\22\0\0\0cups-blockhouse-p1\0\0\4\0\0\0temp"..., 
iov_len=304}], msg_iovlen=2, msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 480
poll([{fd=8, events=POLLIN}], 1, 5000)  = 1 ([{fd=8, revents=POLLIN}])
recvmsg(8, {msg_name=NULL, msg_namelen=0, 
msg_iov=[{iov_base="l\2\1\1=\0\0\0\35\f\0\0.\0\0\0\10\1g\0\1o\0\0\5\1u\0006\3\0\0"...,
 iov_len=2048}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, 
MSG_CMSG_CLOEXEC) = 125
recvmsg(8, {msg_namelen=0}, MSG_CMSG_CLOEXEC) = -1 EAGAIN (Resource temporarily 
unavailable)
open("/etc/cups/ppd/blockhouse-p1.ppd", O_RDONLY) = 20
fcntl(20, F_GETFD)  = 0
fcntl(20, F_SETFD, FD_CLOEXEC)  = 0
read(20, "*PPD-Adobe: \"4.3\"\n*FormatVersion"..., 4096) = 4096
read(20, "ole):  \"\"\n*KOPunch PK521+ZU606-4"..., 4096) = 4096
read(20, "unched false >> \n /KMOptions /Pr"..., 4096) = 4096
read(20, ") /KMMediaColor (None) /KMMediaW"..., 4096) = 4096
read(20, "setKMoptions get exec\"\n*End\n*Med"..., 4096) = 4096
read(20, "/FullBleed false >> /KMOptions /"..., 4096) = 4096
read(20, "deMode false /FullBleed false >>"..., 4096) = 4096
read(20, "rue >> /KMOptions /ProcSet findr"..., 4096) = 4096
read(20, "lfFold/Half-Fold:  \"<< /Collate "..., 4096) = 4096
read(20, ":  \"<< /Collate true >> setpaged"..., 4096) = 4096
read(20, "xec\"\n*AutoTrapping True/On:  \"<<"..., 4096) = 4096
read(20, "PickOne\n*OrderDependency: 10 Any"..., 4096) = 4096
read(20, "Moptions get exec\"\n*End\n*PageReg"..., 4096) = 4096
read(20, "FullBleed false >> /KMOptions /P"..., 4096) = 4096
read(20, " /WideMode true /FullBleed true "..., 4096) = 4096
read(20, "Area 8K/8K:  \"12 12 753 1093\"\n*I"..., 4096) = 4096
read(20, "ze EnvC4\n*UIConstraints: *InputS"..., 4096) = 4096
read(20, "nvChou3\n*UIConstraints: *InputSl"..., 4096) = 4096
read(20, "User4(2nd)\n*UIConstraints: *Inpu"..., 4096) = 4096
read(20, "MediaType Thick1(2nd) *Fold Half"..., 4096) = 4096
read(20, "Thick3(2nd) *Staple 1Staple(Left"..., 4096) = 4096
read(20, "ard\n*UIConstraints: *MediaType T"..., 4096) = 4096
read(20, "diaType Transparency *PageSize L"..., 4096) = 4096
read(20, "6_PostCard\n*UIConstraints: *Medi"..., 4096) = 4096
read(20, "nputSlot Tray2\n*UIConstraints: *"..., 4096) = 4096
read(20, "d) *Fold ZFold1\n*UIConstraints: "..., 4096) = 4096
read(20, "e 220mmx330mm *MediaType TAB\n*UI"..., 4096) = 4096
read(20, " *PageSize EnvISOB5 *Combination"..., 4096) = 4096
read(20, "vChou3 *Punch 4holes\n*UIConstrai"..., 4096) = 4096
read(20, "Size EnvKaku1 *Punch 2holes\n*UIC"..., 4096) = 4096
read(20, "Constraints: *PageSize Env10 *Of"..., 4096) = 4096
read(20, "ageSize A4Extra *Fold TriFold\n*U"..., 4096) = 4096
read(20, "diaType User2(2nd)\n*UIConstraint"..., 4096) = 4096
read(20, "1 *Fold Stitch\n*UIConstraints: *"..., 4096) = 4096
read(20, "raints: *Combination Booklet *Pa"..., 4096) = 4096
read(20,