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.
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.
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
Created attachment 129347 [details] cups 1.1.23 debug log of successful printing the 9 pages
Created attachment 129348 [details] cups 1.2.0 debug log of described problem
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
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.
Peter, please try 1.2.0-1.2 from here: http://people.redhat.com/twaugh/tmp/cups-fc5/ Does that work around the problem?
yes, 1.2.0-1.2 solves the issue, cups is now printing like expected. Thank you for such fast fix.
Great. Thanks for testing it.
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
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.
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.
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.
Please try 1.2.1-1.2 from here: http://people.redhat.com/twaugh/tmp/cups-fc5/ Is it fixed again?
Fixed in 1.2.1-1.2.
Hui, you're releasing updates faster than I'm able to report results ;-) Yes, it's fixed again and working now as expected.
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.