Bug 447548

This bug has been observed with cups-1.2.4-11.18.el5 on RHEL-5.2.

+++ This bug was initially created as a clone of Bug #219330 +++

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.

-- Additional comment from twaugh on 2006-12-12 12:20 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?

-- Additional comment from bnocera on 2007-01-03 05:31 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.

-- Additional comment from twaugh on 2007-01-03 08:35 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.

-- Additional comment from twaugh on 2007-01-03 08:55 EST --
Busy loop condition reported upstream.  Pity we weren't able to catch it with
strace. :-(

-- Additional comment from twaugh on 2007-01-03 13:13 EST --
Can you give cups-libs-1.2.7-1.6.fc6 a try when it's finished building?  It
might fix the busy-loop condition.  You can fetch it from:
porkchop:/mnt/redhat/brewroot/packages/cups/1.2.7/1.6.fc6


-- Additional comment from erik_horn.or.us on 2007-01-05 16:49 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).




-- Additional comment from twaugh on 2007-01-09 06:33 EST --
Please try cups-1.2.7-1.6.fc6 from updates-testing:

yum --enablerepo=updates-testing update 'cups*'

-- Additional comment from erik_horn.or.us on 2007-01-11 17:45 EST --
The updated package didn't help my problem. The strace is the same and the
backtrace is the same except for the addresses.

-- Additional comment from twaugh on 2007-01-12 07:26 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.

-- Additional comment from erik_horn.or.us on 2007-01-12 14:12 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


-- Additional comment from twaugh on 2007-01-15 09:58 EST --
Thanks.  Passed along upstream.

-- Additional comment from updates on 2007-01-22 12:05 EST --
Fixed in update: cups-1.2.7-1.7.fc6

-- Additional comment from erik_horn.or.us on 2007-01-23 12:34 EST --
updated to cups*-1.2.7-1.7.fc6 from updates-testing and I'm still seeing the
same problem.

-- Additional comment from twaugh on 2007-01-24 08:16 EST --
Oops, I shouldn't have closed this.

-- Additional comment from twaugh on 2007-01-24 08:17 EST --
*** Bug 222160 has been marked as a duplicate of this bug. ***

-- Additional comment from twaugh on 2007-01-24 09:12 EST --
Please try cups-1.2.7-1.8.fc6, shortly to appear in updates-testing.


-- Additional comment from erik_horn.or.us on 2007-02-01 13:08 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.