Bug 205619

Summary: cupsd and eggcups take up near 100% cpu usage and must be killed before this is fixed
Product: [Fedora] Fedora Reporter: Jay Modi <jaymode>
Component: cupsAssignee: Tim Waugh <twaugh>
Status: CLOSED ERRATA QA Contact:
Severity: high Docs Contact:
Priority: medium    
Version: 5CC: bugzilla-fedora, ji.cerny, rebcoair
Target Milestone: ---   
Target Release: ---   
Hardware: i686   
OS: Linux   
Whiteboard:
Fixed In Version: 1.2.3-1.6 Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2006-09-22 11:40:48 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On:    
Bug Blocks: 150223    
Attachments:
Description Flags
output of ps -aux command
none
CUPS error log file
none
CUPS error log file with debug2 info level
none
strace.output file that was requested
none
strace.output file
none
cups-config
none
lpstat-s.output.head after cups-1.2.3-1.4 packages
none
cupsd.output
none
lpstat-t.output-1.2.3-1.5
none
error_log-1.2.3-1.5 none

Description Jay Modi 2006-09-07 17:12:00 UTC
From Bugzilla Helper:
User-Agent: Mozilla/5.0 (X11; U; Linux i686; en-US; rv:1.8.0.6) Gecko/20060808 Fedora/1.5.0.6-2.fc5 Firefox/1.5.0.6 pango-text

Description of problem:
cups will use 100% cpu usage until it is killed. Restarting the system does not work. May also be related to OpenOffice as cupsd and eggcups will use high cpu when an openoffice program is open and after it has closed.

Version-Release number of selected component (if applicable):
cups-1.2.3-1.2

How reproducible:
Always


Steps to Reproduce:
1. Start system
2. If not at 100% cpu open OpenOffice
3.

Actual Results:
CPU spikes to 100%, determined processes with command 'ps -aux'

Expected Results:


Additional info:

Comment 1 Jay Modi 2006-09-07 22:49:49 UTC
Created attachment 135819 [details]
output of ps -aux command

Look at the CPU % for cupsd and eggcups

Comment 2 Tim Waugh 2006-09-08 08:30:53 UTC
Please attach your /var/log/cups/error_log file.  Thanks.

Comment 3 Jay Modi 2006-09-08 11:59:33 UTC
Created attachment 135842 [details]
CUPS error log file

Comment 4 Tim Waugh 2006-09-08 12:26:18 UTC
Okay, I don't see anything in there that gives us any clue about what's going
on, so I'll need to enable more debugging output.

Please stop CUPS, as root:

  /sbin/service cups stop

Then clear out the error_log file:

  >/var/log/cups/error_log

Edit the /etc/cups/cupsd.conf file so that the LogLevel line reads:

LogLevel debug2

Then start CUPS again:

  /sbin/service cups start

Now, when you see the CPU usage at 100% again, please attach the
/var/log/cups/error_log file and hopefully it will shed some light on it.  Thanks.

Comment 5 Jay Modi 2006-09-08 16:56:13 UTC
I did what you said to do and the first log file I got was over 1.4gb and the
one I have right now is over 220mb. Do you want me to upload the whole thing?

Comment 6 Tim Waugh 2006-09-08 17:29:55 UTC
You could bzip2 it first, to save bandwidth:

  bzip2 -c /var/log/cups/error_log > error_log.bz2

Or, just take the first 10000 lines or so:

  head -n 10000 /var/log/cups/error_log > error_log.head

I'm sure that will be enough to diagnose the problem.  Thanks!

Comment 7 Jay Modi 2006-09-08 20:54:06 UTC
Created attachment 135879 [details]
CUPS error log file with debug2 info level

Comment 8 Tim Waugh 2006-09-11 09:27:22 UTC
*** Bug 205705 has been marked as a duplicate of this bug. ***

Comment 9 Tim Waugh 2006-09-11 11:42:45 UTC
Next thing I need is the strace.output file from running this command:

  strace -s2048 lpstat -s 2>strace.output

Leave it for a minute or so and then attach the file here.  Thanks.

Comment 10 Jay Modi 2006-09-11 12:22:37 UTC
Created attachment 135982 [details]
strace.output file that was requested

This was used when the CUPS log level was reset to info(I reset it because the
files were huge, but let me know if you want this on debug2)

Comment 11 ron banks 2006-09-11 13:11:18 UTC
Created attachment 135986 [details]
strace.output file

strace.output file

Comment 12 Tim Waugh 2006-09-11 16:20:40 UTC
Please try these test packages (1.2.3-1.3):

  http://people.redhat.com/twaugh/tmp/cups-devel/i386/

Does 1.2.3-1.3 fix the problem?

Comment 13 ron banks 2006-09-11 16:37:56 UTC
No. No difference.

Comment 14 Jay Modi 2006-09-11 20:18:12 UTC
Same here still have to kill cupsd and eggcups to get cpu usage down.

Comment 15 Tim Waugh 2006-09-12 09:00:43 UTC
Thanks for testing.

Here is the upstream bug report:
  http://www.cups.org/str.php?L1968

1.2.3-1.3 contains the 'str1968.patch' patch.

Comment 16 Tim Waugh 2006-09-13 08:55:37 UTC
This might be related to the configuration you have.  If you don't have any
passwords set for remote printers or anything, please do this (as root):

  tar jcf cups-config.tar.bz2 /etc/cups

and attach the cups-config.tar.bz2 file here.  Thanks.

Comment 17 Tim Waugh 2006-09-13 10:34:49 UTC
In addition to attaching the configuration here, please try these experimental
CUPS packages (1.2.3-1.4).  They have extra debugging turned on in two modules
and I think it might be useful to see the debugging from 'lpstat -s'.

  http://people.redhat.com/twaugh/tmp/cups-devel/i386/

Comment 18 ron banks 2006-09-13 11:48:40 UTC
Created attachment 136146 [details]
cups-config

Comment 19 ron banks 2006-09-13 11:51:01 UTC
Created attachment 136147 [details]
lpstat-s.output.head after cups-1.2.3-1.4 packages

still no glory

Comment 20 Jiri Cerny 2006-09-13 13:43:06 UTC
I am seeing the same problem: cups + eggcups eat 100% of processor and fill the
log files with an incredible rate. However, my /var/log/cups/error_log file is
full of lines like

E [13/Sep/2006:15:33:20 +0200] cupsdAcceptClient: skipping getpeercon()

which I did not find in error_logs attached above. The access_log contains many
of lines like

localhost - root [12/Sep/2006:14:34:57 +0200] "POST / HTTP/1.1" 200 124
Get-Printer-Attributes successful-ok

Maybe it can help. I have cups-1.2.3-3

Comment 21 Tim Waugh 2006-09-13 15:13:54 UTC
ron: that's great, I think we're narrowing down on the problem now.  Could you
now please try 'lpstat -s' again, but this time capture the CUPS debugging
output?  Here's how (all as root):

Stop CUPS:
  /sbin/service cups stop

Start CUPS in the foreground:
  /usr/sbin/cupsd -f &>cupsd.output

Then run 'lpstat -s' in another terminal, wait a couple of seconds, and then
control-C both lpstat and cupsd.  I'd really like to see the cupsd.output!  Thanks.

Comment 22 ron banks 2006-09-13 15:26:50 UTC
Created attachment 136162 [details]
cupsd.output

here ya go again!

Comment 23 Tim Waugh 2006-09-13 16:01:19 UTC
Thanks.

Please try these test packages (1.2.3-1.5):

  http://people.redhat.com/twaugh/tmp/cups-devel/i386/

Does 1.2.3-1.5 fix the problem?

Comment 24 ron banks 2006-09-13 16:19:43 UTC
Created attachment 136180 [details]
lpstat-t.output-1.2.3-1.5

some success? run away loop gone. can print now. here is output of 'lpstat-t'

Comment 25 Tim Waugh 2006-09-13 16:22:15 UTC
Great!  I'll get a non-debug build ready.

Comment 26 ron banks 2006-09-13 16:26:43 UTC
Created attachment 136181 [details]
error_log-1.2.3-1.5

Comment 27 Tim Waugh 2006-09-13 16:39:32 UTC
Please try these test packages (1.2.3-1.6):

  http://people.redhat.com/twaugh/tmp/cups-devel/i386/

The extra debugging information is removed, but they have my wbuffer fix.  These
should work normally.

ron, Jiri: let me know how they work for you.  Thanks!

Comment 28 Tim Waugh 2006-09-13 16:58:56 UTC
Of course, you can now change your /etc/cups/cupsd.conf 'LogLevel' line back to:

LogLevel info

Comment 29 ron banks 2006-09-13 17:30:58 UTC
As far as I'm concerned this bug is squashed. Thanks Tim.!

Comment 30 Fred New 2006-09-13 17:39:38 UTC
I've been tracking this bug from 205705, and this fix works for me, too.

Comment 31 Jay Modi 2006-09-13 20:05:41 UTC
Also works for me. Thanks!

Comment 32 Jiri Cerny 2006-09-13 20:34:38 UTC
Here it works too. Thanks. Jiri.

Comment 33 Tim Waugh 2006-10-23 12:46:37 UTC
*** Bug 206075 has been marked as a duplicate of this bug. ***