Bug 192034 - cups-1.2.0-1.1 USB driver broken, can't print larger documents anymore, running in USB timeout
cups-1.2.0-1.1 USB driver broken, can't print larger documents anymore, runni...
Status: CLOSED ERRATA
Product: Fedora
Classification: Fedora
Component: cups (Show other bugs)
5
i386 Linux
medium Severity high
: ---
: ---
Assigned To: Tim Waugh
:
Depends On:
Blocks: FC6Target
  Show dependency treegraph
 
Reported: 2006-05-16 18:52 EDT by Peter Bieringer
Modified: 2007-11-30 17:11 EST (History)
0 users

See Also:
Fixed In Version: 1.2.1-1.2
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2006-05-23 18:12:02 EDT
Type: ---
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
cups 1.1.23 debug log of successful printing the 9 pages (15.84 KB, application/x-gzip)
2006-05-17 14:01 EDT, Peter Bieringer
no flags Details
cups 1.2.0 debug log of described problem (28.05 KB, application/x-gzip)
2006-05-17 14:02 EDT, Peter Bieringer
no flags Details

  None (edit)
Description Peter Bieringer 2006-05-16 18:52:26 EDT
Description of problem:
After upgrading to cups-1.2.0-1.1 the USB driver must be broken. I can print a
single small page (e.g. /etc/hosts) but if I print larger documents, either
printing is stopped at the beginning of the first or second page.

Version-Release number of selected component (if applicable):
cups-1.2.0-1.1

How reproducible:
Everytime I upgrade to 1.2.0-1.1, 1.1.23-30.2 is working fine (again after
downgrade)

Steps to Reproduce:
1. upgrade to cups 1.2.0-1.1
2. print a 8 page PS file 

Actual results:
Hanging after beginning of printing

Expected results:
Working like after downgrading to 1.1.23-30.2

Additional info:
Printer is a Canon iP4000
Mainboard is a ASUS CUBX
USB is 1.1
Printer is currently connected through a USB hub, but problem also exists without

Following kernels were tested during debugging:
kernel-2.6.15-1.2054_FC5
kernel-2.6.16-1.2111_FC5
Problem exists independend from upper shown kernel versions.


# lsusb
Bus 001 Device 018: ID 04a9:1093 Canon, Inc.
Bus 001 Device 017: ID 05e3:0605 Genesys Logic, Inc. USB 2.0 Hub [ednet]
Bus 001 Device 016: ID 058f:9254 Alcor Micro Corp. Hub
Bus 001 Device 001: ID 0000:0000

cups log didn't show anything so I debugged deeper using strace and found that
the job usb:/dev/usb/lp0 was hanging:

# strace -s 80 -p 13592
Process 13592 attached - interrupt to quit
select(4, NULL, [3], NULL, {0, 128000}) = 0 (Timeout)
write(3,
"\0\273BST:84;PID:01,01,00;TRB:00A800;CHD:CL;LVR:GAL,AT;MID:B146F4;HCU:00000004,K+00,"...,
187) = -1 EAGAIN (Resour ce temporarily unavailable)
select(4, NULL, [3], NULL, {1, 0})      = 0 (Timeout)
write(3,
"\0\273BST:84;PID:01,01,00;TRB:00A800;CHD:CL;LVR:GAL,AT;MID:B146F4;HCU:00000004,K+00,"...,
187) = -1 EAGAIN (Resour ce temporarily unavailable)
select(4, NULL, [3], NULL, {1, 0})      = 0 (Timeout)
write(3,
"\0\273BST:84;PID:01,01,00;TRB:00A800;CHD:CL;LVR:GAL,AT;MID:B146F4;HCU:00000004,K+00,"...,
187) = -1 EAGAIN (Resour ce temporarily unavailable)
select(4, NULL, [3], NULL, {1, 0})      = 0 (Timeout)
write(3,
"\0\273BST:84;PID:01,01,00;TRB:00A800;CHD:CL;LVR:GAL,AT;MID:B146F4;HCU:00000004,K+00,"...,
187) = -1 EAGAIN (Resour ce temporarily unavailable)
select(4, NULL, [3], NULL, {1, 0} <unfinished ...>
Process 13592 detached

Debugging usbmon/debugfs shows me, that suddenly communication stops, no traffic
was seen anymore.

I can reproduce the problem, so if I get a request what/how more to debug, I can
try to dig further into.
Comment 1 Tim Waugh 2006-05-17 07:29:01 EDT
Please edit /etc/cups/cupsd.conf and change the 'LogLevel' line to read:

  LogLevel debug2

Then stop cups:

  /sbin/service cups stop

Then clear out the error_log file

  >/var/log/cups/error_log

Then start cups again:

  /sbin/service cups start

Print a file, and when it fails please attach /var/log/cups/error_log.  Thanks.
Comment 2 Peter Bieringer 2006-05-17 13:57:06 EDT
Problem reproduced, debug output follows.
I have forgotten that I'm using Turboprint as printer driver for the Canon iP4000

Here the steps:

# service cups start

$ lpr -P tp0 /tmp/test.ps
$ lpq -P tp0
tp0 is ready and printing
Rank    Owner   Job     File(s)                         Total Size
active  peter   812     test.ps                         10574848 bytes

...hanging

$ lprm 812

Related processes:

10885 ?        S      0:00 usb:/dev/usb/lp0 812 peter test.ps 1 cpi=10 lpi=6
PageSize=A4 Resolution=600x600dpi zedoColorModel=RGB zedoDithering=ErrorDif
fusion MediaType=Plainpaper_4 InputSlot=ButtonSelect Duplex=None
zedoColorCorrection=1 zedoUserColor=1 zedoMirror=0 zedoDuplexAdjust=0
zedoBrightness=0 ze doContrast=0 zedoGamut=0 zedoIntensity=0 zedoGamma=220
zedoColorY=0 zedoColorC=0 zedoColorM=0 zedoColorK=0
job-uuid=urn:uuid:e1bca8f7-86dc-3560-5c81-719ab de7f65a
10904 ?        S      0:11 /usr/bin/tpprint -a0 -e1 -s8268x11693 -v2
-l/var/log/turboprint_cups.log ---cpi=10 ---lpi=6 ---PageSize=A4
---Resolution=600x60 0dpi ---zedoColorModel=RGB
---zedoDithering=ErrorDiffusion ---MediaType=Plainpaper_4
---InputSlot=ButtonSelect ---Duplex=None ---zedoColorCorrection=1 ---
zedoUserColor=1 ---zedoMirror=0 ---zedoDuplexAdjust=0 ---zedoBrightness=0
---zedoContrast=0 ---zedoGamut=0 ---zedoIntensity=0 ---zedoGamma=220
---zedoColo rY=0 ---zedoColorC=0 ---zedoColorM=0 ---zedoColorK=0
---job-uuid=urn:uuid:e1bca8f7-86dc-3560-5c81-719abde7f65a
--ppdfile=/etc/cups/ppd/tp0.ppd --psheader= /tmp/pstoturboprint10884.chunk
/tmp/pstoturboprint10884.fifo -
10905 ?        S      0:00 /usr/share/turboprint/lib/tpstdin --paste
/tmp/pstoturboprint10884.chunk
10906 ?        S      0:06 gs -sDEVICE=pcx24b -r600x600 -g4960x7015 -dSAFER
-dNOPAUSE -dBATCH -sOutputFile=/tmp/pstoturboprint10884.fifo -


# kill 10885 10904 10905 10906

-> first page leaves the printer, a second one was feeded

* disconnect printer from USB
-> second page leaves the printer
Comment 3 Peter Bieringer 2006-05-17 14:01:01 EDT
Created attachment 129347 [details]
cups 1.1.23 debug log of successful printing the 9 pages
Comment 4 Peter Bieringer 2006-05-17 14:02:33 EDT
Created attachment 129348 [details]
cups 1.2.0 debug log of described problem
Comment 5 Peter Bieringer 2006-05-17 14:08:01 EDT
BTW: there are additional minor bugs in cups-1.2.0

After booting:

Remounting root filesystem in read-write mode:             [  OK  ]
Mounting local filesystems:                                [  OK  ]
Enabling local filesystem quotas:                          [  OK  ]
rm: cannot remove `/var/run/cups/certs': Is a directory
Enabling swap space:                                       [  OK  ]
INIT: Entering runlevel: 3


And in cups error log:
E [17/May/2006:19:45:52 +0200] Unable to set ACLs on root certificate
"/var/run/cups/certs/0" - Operation not supported
Comment 6 Tim Waugh 2006-05-18 06:33:15 EDT
Reported upstream:

  http://cups.org/str.php?L1705

The 'Unable to set ACLs' message is normal if you haven't mounted the filesystem
with the 'acl' option -- and by default we don't.

The 'rm: cannot remove' message seems to be an initscripts bug: please file a
separate report for that.
Comment 7 Tim Waugh 2006-05-18 13:21:41 EDT
Peter, please try 1.2.0-1.2 from here:

  http://people.redhat.com/twaugh/tmp/cups-fc5/

Does that work around the problem?
Comment 8 Peter Bieringer 2006-05-18 13:36:54 EDT
yes, 1.2.0-1.2 solves the issue, cups is now printing like expected. Thank you
for such fast fix.
Comment 9 Tim Waugh 2006-05-18 13:40:27 EDT
Great.  Thanks for testing it.
Comment 10 Peter Bieringer 2006-05-18 13:52:42 EDT
Relating to the rc.sysinit issue described in comment
https://bugzilla.redhat.com/bugzilla/show_bug.cgi?id=192034#c5

I filed now a low-prio bug:
https://bugzilla.redhat.com/bugzilla/show_bug.cgi?id=192264
Comment 11 Tim Waugh 2006-05-22 12:24:40 EDT
Could you please try cups-1.2.0-1.4?  The 1.2.0-1.2 package unconditionally
disabled the fetching of back-channel data, but 1.2.0-1.4 contains the upstream
fix which is to only disable it for Canon printers.

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

should fetch it.  Thanks.
Comment 12 Peter Bieringer 2006-05-22 15:24:43 EDT
This version is not working proper, printing is very slow. I read the comments
in http://cups.org/str.php?L1705, have I to configure a switch now?

strace shows:
 6314 ?        S      0:00 usb:/dev/usb/lp0 856 root test.ps 1
printer-state-change-time=1147817188 printer-state-reasons=none
printer-type=159836 cpi=10 lpi=6
job-uuid=urn:uuid:e461059c-307e-317e-4a9a-096dcfd4d1

# strace -p 6314
Process 6314 attached - interrupt to quit
select(4, NULL, [3], NULL, {0, 796000}) = 0 (Timeout)
write(3, "\0\273BST:84;PID:01,01,01;TRB:00A800"..., 187) = -1 EAGAIN (Resource
temporarily unavailable)
write(4, "vyp(R\375\0\377\1\3\3\0[\34\376\1\3\t\33T\3\376\33-R\3"..., 8192) = 8192
read(0, "[(\36\t\0Q\0Q\0\0\t\34\34%\t\1\t[\37x\36Q[_\227x\t[x\34"..., 8192) = 8192
select(5, [4], [4], NULL, NULL)         = 2 (in [4], out [4])
read(4, "\0\273BST:84;PID:01,01,01;TRB:00A800"..., 1024) = 187
write(2, "DEBUG: Received 187 bytes of bac"..., 48) = -1 EPIPE (Broken pipe)
--- SIGPIPE (Broken pipe) @ 0 (0) ---
select(4, NULL, [3], NULL, {1, 0})      = 0 (Timeout)
write(3, "\0\273BST:84;PID:01,01,01;TRB:00A800"..., 187) = -1 EAGAIN (Resource
temporarily unavailable)
write(4, "[(\36\t\0Q\0Q\0\0\t\34\34%\t\1\t[\37x\36Q[_\227x\t[x\34"..., 8192) = 8192
read(0, "o[v\37[^\36ov\37[p(\'py(yo[\'y((]^\376y\27\315o%"..., 8192) = 8192
select(5, [4], [4], NULL, NULL)         = 2 (in [4], out [4])
read(4, "\0\273BST:84;PID:01,01,01;TRB:00A800"..., 1024) = 187
write(2, "DEBUG: Received 187 bytes of bac"..., 48) = -1 EPIPE (Broken pipe)
--- SIGPIPE (Broken pipe) @ 0 (0) ---
select(4, NULL, [3], NULL, {1, 0} <unfinished ...>
Process 6314 detached


This version is better than the initial one, where printing hangs completly, but
one printer head move each 20 seconds is far away from the speed of the working
solution of your intermediate workaround.

BTW: turboprint is available at http://www.turboprint.de/, without a license,
the turboprint logo is printed randomly on the page, but software is full
functional at all. I recommend, that one of the cups developers should try to
get a Canon printer temporary to fix that problem in upstream by
developer-controlled tests.
Comment 13 Tim Waugh 2006-05-22 18:00:22 EDT
Ah, I see what happened.  The 'don't read back-channel data' thing should
automatically be triggered by checking that it's a Canon printer -- but it does
that by checking that the URI is usb://Canon/...

Unfortunately, the URI in this case is usb:/dev/usb/lp0.  This kind of URI is
actually no longer supported upstream; it's specially allowed in the Fedora Core
package.

So I'll fix the check to include that type of URI as well.
Comment 14 Tim Waugh 2006-05-23 05:33:29 EDT
Please try 1.2.1-1.2 from here:

  http://people.redhat.com/twaugh/tmp/cups-fc5/

Is it fixed again?
Comment 15 Fedora Update System 2006-05-23 14:40:46 EDT
Fixed in 1.2.1-1.2.
Comment 16 Peter Bieringer 2006-05-23 17:16:00 EDT
Hui, you're releasing updates faster than I'm able to report results ;-)
Yes, it's fixed again and working now as expected.
Comment 17 Tim Waugh 2006-05-23 18:12:02 EDT
Oops -- comment #15 was an automated one. :-)

I released 1.2.1-1.2 because it fixed some other widely-seen problems, so I was
crossing my fingers with it fixing this bug too.  Glad it does; thanks for
testing and getting back to me.

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