Bug 219330 - ipp backend eats all my CPU
ipp backend eats all my CPU
Status: CLOSED ERRATA
Product: Fedora
Classification: Fedora
Component: cups (Show other bugs)
6
All Linux
medium Severity medium
: ---
: ---
Assigned To: Tim Waugh
: Reopened
Depends On:
Blocks: FC6Update
  Show dependency treegraph
 
Reported: 2006-12-12 11:57 EST by Bastien Nocera
Modified: 2007-11-30 17:11 EST (History)
3 users (show)

See Also:
Fixed In Version: 1.2.7-1.8.fc6
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2007-02-06 12:31:17 EST
Type: ---
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)


External Trackers
Tracker ID Priority Status Summary Last Updated
CUPS Bugs and Features 2109 None None None Never
CUPS Bugs and Features 2179 None None None Never

  None (edit)
Description Bastien Nocera 2006-12-12 11:57:42 EST
IPP backend is eating all my CPU

Backtrace looks like that:
#0  0x0015d402 in __kernel_vsyscall ()
#1  0x00d5ae56 in time () from /lib/libc.so.6
#2  0x00462876 in httpRead2 (http=0x93a4438, buffer=0xbfa4fb89 "L�", length=8)
    at http.c:1174
#3  0x00467f26 in ipp_read_http (http=0x93a4438, buffer=0xbfa4fb89 "L�", 
    length=8) at ipp.c:2759
#4  0x00467aa5 in ippReadIO (src=0x93a4438, cb=0x467d80 <ipp_read_http>, 
    blocking=1, parent=0x0, ipp=0x93a8ae8) at ipp.c:1054
#5  0x00467ce9 in ippRead (http=0x0, ipp=0x481ddc) at ipp.c:991
#6  0x00473c52 in cupsDoFileRequest (http=0x93a4438, request=0x93a8bb0, 
    resource=0xbfa6ac08 "/printers/GSS", filename=0x0) at request.c:346
#7  0x004741ee in cupsDoRequest (http=0x93a4438, request=0x93a8bb0, 
    resource=0xbfa6ac08 "/printers/GSS") at request.c:451
#8  0x00c4fd75 in check_printer_state (http=0x93a4438, 
    uri=0xbfa6a808 "ipp://file.surrey.redhat.com:631/printers/GSS", 
    resource=0xbfa6ac08 "/printers/GSS", user=0xbfa6cab6 "bnocera", version=1)
    at ipp.c:1225
#9  0x00c52002 in main (argc=7, argv=0xbfa6b8b4) at ipp.c:1089

I've not been able to print to this printer (GSS) since upgrading to FC6. It
worked fine under RHEL4.
Comment 1 Tim Waugh 2006-12-12 12:20:03 EST
You haven't said which version of CUPS you're using, but the line numbers don't
seem to match either the current updates-testing package (1.2.7-1.5.fc6) or the
current updates package (1.2.7-1.3.fc6).  In fact, it would appear to match
cups-1.2.4-9.

So try applying the updates.

You've not said how repeatable this is (is this the reason you've not been able
to print since FC6?).  Does the ipp backend do this every time you submit a job
to that printer?
Comment 2 Bastien Nocera 2007-01-03 05:31:52 EST
cups-libs-1.2.7-1.5.fc6
cups-debuginfo-1.2.7-1.5.fc6

I still get the same thing:
#0  0x00764402 in __kernel_vsyscall ()
#1  0x00448e56 in time () from /lib/libc.so.6
#2  0x002ae6f6 in httpRead2 (http=0x9342438, buffer=0xbfa52e59 ",A", length=8)
at http.c:1232
#3  0x002b4386 in ipp_read_http (http=0x9342438, buffer=0xbfa52e59 ",A",
length=8) at ipp.c:2759
#4  0x002b3f05 in ippReadIO (src=0x9342438, cb=0x2b41e0 <ipp_read_http>,
blocking=1, parent=0x0, ipp=0x9346470) at ipp.c:1054
#5  0x002b4149 in ippRead (http=0x0, ipp=0x2cf8a4) at ipp.c:991
#6  0x002c03f2 in cupsDoFileRequest (http=0x9342438, request=0x93422f8,
resource=0xbfa6de68 "/printers/GSS", filename=0xbfa70d3a
"/var/spool/cups/d00013-001") at request.c:346
#7  0x0085846b in main (argc=7, argv=0xbfa6ec14) at ipp.c:971

I haven't been able to print to this particular printer since FC6 was installed
on this machine (it worked great under RHEL4 before that). I can repeat it every
time trying to print to this particular printer.
Comment 3 Tim Waugh 2007-01-03 08:35:06 EST
Part of the problem here is that the remote error (that the LPD host is down)
does not get reportedly locally.  I reported this upstream in November.
Comment 4 Tim Waugh 2007-01-03 08:55:20 EST
Busy loop condition reported upstream.  Pity we weren't able to catch it with
strace. :-(
Comment 6 Erik Horn 2007-01-05 16:49:11 EST
I have an issue that looks very similar to this with samba printing. I was going
to file it under samba until I found this entry. If I need to file this as a
seperate issue please let me know.

The problem that I'm having is that samba processes will occasionally go to 100%
cpu usage and stay there until killed. On our system this happens several times
a day on average.

Here is the information I gathered for my problem.

Strace of afflicted process:

Process 30782 attached - interrupt to quit
time(NULL)                              = 1167861753
recv(27, "", 2048, 0)                   = 0
time(NULL)                              = 1167861753
recv(27, "", 2048, 0)                   = 0
time(NULL)                              = 1167861753
recv(27, "", 2048, 0)                   = 0
time(NULL)                              = 1167861753
recv(27, "", 2048, 0)                   = 0
time(NULL)                              = 1167861753
recv(27, "", 2048, 0)                   = 0
time(NULL)                              = 1167861753
recv(27, "", 2048, 0)                   = 0
time(NULL)                              = 1167861753
(it keeps going until killed)


checked to see what it was stuck on

# ls -al /proc/30782/fd/27
l-wx------ 1 root root 64 Jan  3 13:40 /proc/30782/fd/27 -> socket:[13057635]


Checking to see what it's trying to talk to

# grep 13057635 /proc/net/tcp
 450: 0100007F:9CCD 0100007F:0277 08 00000000:00000000 00:00000000 00000000    
0        0 13057635 1 cde21a80 205 40 26 2 100  

# netstat -np |grep 30782
tcp       38      0 66.xxx.xxx.xxx:52436        66.xxx.xxx.xxx:389         
CLOSE_WAIT  30782/smbd          
tcp        0      0 66.xxx.xxx.xxx:445          10.xx.xx.xxx:1112          
ESTABLISHED 30782/smbd          
tcp        0      0 127.0.0.1:40141             127.0.0.1:631              
CLOSE_WAIT  30782/smbd  

Backstrace of process

#0  0x00110402 in __kernel_vsyscall ()
#1  0x00170061 in recv () from /lib/libpthread.so.0
#2  0x00dfcb18 in httpRead2 () from /usr/lib/libcups.so.2
#3  0x00e02386 in ippRead () from /usr/lib/libcups.so.2
#4  0x00e01855 in ippReadIO () from /usr/lib/libcups.so.2
#5  0x00e02149 in ippRead () from /usr/lib/libcups.so.2
#6  0x00e0e3f2 in cupsDoFileRequest () from /usr/lib/libcups.so.2
#7  0x00e0e98e in cupsDoRequest () from /usr/lib/libcups.so.2
#8  0x00c1ebd4 in cups_cache_reload () from /usr/sbin/smbd
#9  0x00c1caaf in pcap_cache_reload () from /usr/sbin/smbd
#10 0x00ceaca1 in reload_printers () from /usr/sbin/smbd
#11 0x00ad1d33 in check_reload () from /usr/sbin/smbd
#12 0x00ad1e55 in check_reload () from /usr/sbin/smbd
#13 0x00ad278e in smbd_process () from /usr/sbin/smbd
#14 0x00cec8e0 in main () from /usr/sbin/smbd


Not all of the packages on this server are up to date, but the ones that I
thought were relevent to this problem are:

samba-3.0.23c-2
cups-1.2.7-1.5.fc6
cups-libs-1.2.7-1.5.fc6
glibc-2.5-3

It appears to me that the cups library is in a loop reading from the network
connection to cupsd (127.0.0.1:631) which appears to be closed (according to
netstat).


Comment 7 Tim Waugh 2007-01-09 06:33:12 EST
Please try cups-1.2.7-1.6.fc6 from updates-testing:

yum --enablerepo=updates-testing update 'cups*'
Comment 8 Erik Horn 2007-01-11 17:45:06 EST
The updated package didn't help my problem. The strace is the same and the
backtrace is the same except for the addresses.
Comment 9 Tim Waugh 2007-01-12 07:26:59 EST
Please install cups-debuginfo from updates-testing-debuginfo so we can get a
better backtrace (i.e. with line numbers):

yum --enablerepo=updates-testing-debuginfo install cups-debuginfo

Thanks.
Comment 10 Erik Horn 2007-01-12 14:12:09 EST
Here is a backtrace after the debuginfo was installed.


#0  0x00830402 in __kernel_vsyscall ()
#1  0x009ed061 in recv () from /lib/libpthread.so.0
#2  0x009a6b18 in httpRead2 (http=0x93ef1c0, buffer=0xbfb8a899 "none", length=1)
at /usr/include/bits/socket2.h:35
#3  0x009ac376 in ipp_read_http (http=0x93ef1c0, buffer=0xbfb8a899 "none",
length=1) at ipp.c:2759
#4  0x009ab84d in ippReadIO (src=0x93ef1c0, cb=0x9ac1d0 <ipp_read_http>,
blocking=1, parent=0x0, ipp=0x9406340) at ipp.c:1101
#5  0x009ac139 in ippRead (http=0x9c7884, ipp=0xbfb8a760) at ipp.c:991
#6  0x009b83e2 in cupsDoFileRequest (http=0x93ef1c0, request=0x93c5570,
resource=0x4fc159 "/", filename=0x0) at request.c:346
#7  0x009b897e in cupsDoRequest (http=0x93ef1c0, request=0x93c5570,
resource=0x4fc159 "/") at request.c:451
#8  0x003d1bd4 in cups_cache_reload () from /usr/sbin/smbd
#9  0x003cfaaf in pcap_cache_reload () from /usr/sbin/smbd
#10 0x0049dca1 in reload_printers () from /usr/sbin/smbd
#11 0x00284d33 in check_reload () from /usr/sbin/smbd
#12 0x00284e55 in check_reload () from /usr/sbin/smbd
#13 0x0028578e in smbd_process () from /usr/sbin/smbd
#14 0x0049f8e0 in main () from /usr/sbin/smbd
Comment 11 Tim Waugh 2007-01-15 09:58:36 EST
Thanks.  Passed along upstream.
Comment 12 Fedora Update System 2007-01-22 12:05:19 EST
Fixed in update: cups-1.2.7-1.7.fc6
Comment 13 Erik Horn 2007-01-23 12:34:42 EST
updated to cups*-1.2.7-1.7.fc6 from updates-testing and I'm still seeing the
same problem.
Comment 14 Tim Waugh 2007-01-24 08:16:19 EST
Oops, I shouldn't have closed this.
Comment 15 Tim Waugh 2007-01-24 08:17:56 EST
*** Bug 222160 has been marked as a duplicate of this bug. ***
Comment 16 Tim Waugh 2007-01-24 09:12:19 EST
Please try cups-1.2.7-1.8.fc6, shortly to appear in updates-testing.
Comment 17 Erik Horn 2007-02-01 13:08:09 EST
After running cups-1.2.7-1.8.fc6 for three days the problem has not reoccurred,
so I believe the problem is fixed. 

Note You need to log in before you can comment on or make changes to this bug.