Home | Docs | Forums | Lists | Bugs | Planet | Store | GMN | Get Gentoo!
Not eligible to see or edit group visibility for this bug.
View Bug Activity | Format For Printing | XML | Clone This Bug
After printing one page (Problem does not occur an all pages) I try to print another page after the printer _has stopped_ printing the first page CUPS printing will show a message like "Gutenprint Printing page 1, 10%" and the printer prints nothing and the message persists. The filter and usb processes do not die. Printing will resume after any of the following operations: 1. Restart of cupsd 2. Restart of printer via power button 3. Typing: lsusb -v If I boot to kernel-2.6.18-gentoo-r16 with no other change to the system this problem does not occur (and pages that were stuck in the queue with the new kernel configuration are printed) although starting of a new print job is slow also on this kernel (maybe about 20 seconds). Booting back to kernel 2.6.26-gentoo-r4 or 2.6.25-gentoo-r9 brings back the problem. Reproducible: Always Steps to Reproduce: 0. Requires CUPS and printer (Canond BJC-3000?) connected via USB 1. Browse to address http://tyvi.elma.fi/index.html and print page once 2. Wait until the printer has completely stopped printing 3. Try printing the same page again. Actual Results: Second print job does not get printed. The CUPS Administration tool shows the message "Gutenprint Printing page 1, 10%" until I type lsusb -v (-v is required). Expected Results: In my opinion the printer should print the second job or page without me performing any extra tricks in between. Kernel version with problem: 2.6.26-gentoo-r4 Kernel version without problem: 2.6.18-gentoo-r6 Cups version net-print/cups 1.3.9-r1 (same problem also with 1.3.8-r2) Printer: Canon BJC-3000 connected via usb Printer-driver: net-print/gutenprint-5.1.4 (I tried also with the bjc600 driver ) The last messages in /var/log/cups/error_log: I [16/Dec/2008:22:20:16 +0200] [Job ???] Request file type is application/postscript. I [16/Dec/2008:22:20:16 +0200] [Job 809] Adding start banner page "none". I [16/Dec/2008:22:20:16 +0200] [Job 809] Adding end banner page "none". I [16/Dec/2008:22:20:16 +0200] [Job 809] File of type application/postscript queued by "tuomas". I [16/Dec/2008:22:20:16 +0200] [Job 809] Queued on "gimp-printer" by "tuomas". I [16/Dec/2008:22:20:16 +0200] [Job 809] Started filter /usr/libexec/cups/filter/pstops (PID 6156) I [16/Dec/2008:22:20:16 +0200] [Job 809] Started filter /usr/libexec/cups/filter/pstoraster (PID 6157) I [16/Dec/2008:22:20:16 +0200] [Job 809] Started filter /usr/libexec/cups/filter/rastertogutenprint.5.1 (PID 6158) I [16/Dec/2008:22:20:16 +0200] [Job 809] Started backend /usr/libexec/cups/backend/usb (PID 6159) ### This is where the processing stops, the processes do not die emerge --info Portage 2.1.4.5 (default/linux/x86/2008.0/desktop, gcc-4.1.2, glibc-2.6.1-r0, 2.6.26-gentoo-r4 i686) ================================================================= System uname: 2.6.26-gentoo-r4 i686 Intel(R) Pentium(R) 4 CPU 2.40GHz Timestamp of tree: Tue, 16 Dec 2008 16:30:01 +0000 app-shells/bash: 3.2_p33 dev-java/java-config: 1.3.7, 2.1.6 dev-lang/python: 2.5.2-r7 sys-apps/baselayout: 1.12.11.1 sys-apps/sandbox: 1.2.18.1-r2 sys-devel/autoconf: 2.13, 2.61-r2 sys-devel/automake: 1.8.5-r3, 1.9.6-r2, 1.10.1-r1 sys-devel/binutils: 2.18-r3 sys-devel/gcc-config: 1.4.0-r4 sys-devel/libtool: 1.5.26 virtual/os-headers: 2.6.23-r3 ACCEPT_KEYWORDS="x86" CBUILD="i686-pc-linux-gnu" CFLAGS="-O2 -march=pentium4 -fomit-frame-pointer -pipe" CHOST="i686-pc-linux-gnu" CONFIG_PROTECT="/etc /usr/kde/3.5/env /usr/kde/3.5/share/config /usr/kde/3.5/shutdown /usr/share/config /var/lib/hsqldb" CONFIG_PROTECT_MASK="/etc/ca-certificates.conf /etc/env.d /etc/env.d/java/ /etc/fonts/fonts.conf /etc/gconf /etc/revdep-rebuild /etc/terminfo /etc/texmf/web2c /etc/udev/rules.d" CXXFLAGS="-O2 -march=pentium4 -fomit-frame-pointer -pipe" DISTDIR="/usr/portage/distfiles" FEATURES="distlocks metadata-transfer sandbox sfperms strict unmerge-orphans userfetch" GENTOO_MIRRORS="ftp://trumpetti.atm.tut.fi/gentoo/" LANG="fi_FI.UTF-8" LDFLAGS="-Wl,-O1" MAKEOPTS="-j2" PKGDIR="/usr/portage/packages" PORTAGE_RSYNC_OPTS="--recursive --links --safe-links --perms --times --compress --force --whole-file --delete --stats --timeout=180 --exclude=/distfiles --exclude=/local --exclude=/packages" PORTAGE_TMPDIR="/var/tmp" PORTDIR="/usr/portage" PORTDIR_OVERLAY="/usr/local/portage" SYNC="rsync://rsync.gentoo.org/gentoo-portage" USE="X acl acpi alsa avi berkdb bluetooth branding bzip2 cairo cdr cli cracklib crypt cups dbus dri dts dvd dvdr dvdread eds emboss encode esd evo exif fam fdftk ffmpeg firefox foomaticdb fortran ftp gdbm gif gnome gphoto2 gpm gstreamer gtk hal iconv imagemagick imap ipv6 isdnlog java javascript jikes jpeg kde kdeenablefinal ldap libnotify live mad matroska matrox mbox midi mikmod mime mozilla mp3 mpeg mudflap nas ncurses nls nptl nptlonly ofx ogg oggvorbis opengl openmp pam pcre pdf perl pic png ppds pppd python qt3 qt3support qt4 quicktime readline reflection scanner sdl session simplexml smartcard sockets spell spl ssl startup-notification svg symlink sysfs tcpd theora tiff truetype unicode usb v4l vorbis win32codecs wmf x86 xanim xine xml xorg xv xvid zlib" ALSA_CARDS="ali5451 als4000 atiixp atiixp-modem bt87x ca0106 cmipci emu10k1 emu10k1x ens1370 ens1371 es1938 es1968 fm801 hda-intel intel8x0 intel8x0m maestro3 trident usb-audio via82xx via82xx-modem ymfpci" ALSA_PCM_PLUGINS="adpcm alaw asym copy dmix dshare dsnoop empty extplug file hooks iec958 ioplug ladspa lfloat linear meter mmap_emul mulaw multi null plug rate route share shm softvol" APACHE2_MODULES="actions alias auth_basic authn_alias authn_anon authn_dbm authn_default authn_file authz_dbm authz_default authz_groupfile authz_host authz_owner authz_user autoindex cache dav dav_fs dav_lock deflate dir disk_cache env expires ext_filter file_cache filter headers include info log_config logio mem_cache mime mime_magic negotiation rewrite setenvif speling status unique_id userdir usertrack vhost_alias" ELIBC="glibc" INPUT_DEVICES="keyboard mouse" KERNEL="linux" LCD_DEVICES="bayrad cfontz cfontz633 glk hd44780 lb216 lcdm001 mtxorb ncurses text" USERLAND="GNU" VIDEO_CARDS="mga" Unset: CPPFLAGS, CTARGET, EMERGE_DEFAULT_OPTS, FFLAGS, INSTALL_MASK, LC_ALL, LINGUAS, PORTAGE_COMPRESS, PORTAGE_COMPRESS_FLAGS, PORTAGE_RSYNC_EXTRA_OPTS
Created an attachment (id=175515) [details] The output of the command lsusb -v that resumed printing
Created an attachment (id=175517) [details] dmesg output for kernel 2.6.26-gentoo-r4
Created an attachment (id=175519) [details] dmesg output for kernel 2.6.18-gentoo-r6
Created an attachment (id=175523) [details] Cups error_log There is no error here according cups, just a very long wait until the printer is able to accept data again and the job can be finished.
Created an attachment (id=175577) [details] .config for kernel 2.6.26-gentoo-r4
Created an attachment (id=175578) [details] .config for kernel 2.6.18-gentoo-r6
Ok just a couple of things to do Please try the latest gutenprint driver ( 5.1.7 ). Also what package contains the bjc600 driver ? Finally , you could try to use the latest sys-kernel/git-sources to see if you can reproduce this issue
Please try printing the page from the terminal,for example using the lp command. It may provide more output and we'll be able to figure out if it's a kernel-space problem.
(In reply to comment #8) > Please try printing the page from the terminal,for example using the lp > command. > It may provide more output and we'll be able to figure out if it's a > kernel-space problem. > Hi. This did not give any error message. The printer spooler accepts job. It just seems that the printer does not get the message through that it is able to accept more data. Here is the output anyway. I have not yet tested the procedures Markos suggested. tuomas@hiiru ~/scratch $ lp -d gimp-printer test.pdf request id is gimp-printer-813 (1 file(s)) tuomas@hiiru ~/scratch $ lp -d gimp-printer test.pdf request id is gimp-printer-814 (1 file(s)) tuomas@hiiru ~/scratch $ lpq -P gimp-printer gimp-printer is ready and printing Rank Owner Job File(s) Total Size active tuomas 814 test.pdf 76800 bytes tuomas@hiiru ~/scratch $ lpq -P gimp-printer gimp-printer is ready and printing Rank Owner Job File(s) Total Size active tuomas 814 test.pdf 76800 bytes tuomas@hiiru ~/scratch $ su Password: hiiru scratch # lsusb -v ### And job 814 is finally printed
(In reply to comment #7) > Ok just a couple of things to do > > Please try the latest gutenprint driver ( 5.1.7 ). Also what package contains > the bjc600 driver ? Hi. I tried with the new driver: emerged driver, restarted cupsd, re-installed printer. Tried printing. The results are identical to the ones in comment #9. According to http://www.linuxprinting.org/show_driver.cgi?driver=bjc600&fromprinter=Canon-BJC-3000 bjc600 Type: Ghostscript built-in Ghostscript's built-in standard driver for Canon's inkjet printers. NOTE: Due to a bug GPL Ghostscript 8.63 crashes when using this driver with PDF input data. With PostScript the driver works just fine. I have currently app-text/ghostscript-gpl uninstalled and app-text/ghostscript-esp-8.15.4-r1 installed. > > Finally , you could try to use the latest sys-kernel/git-sources to see if you > can reproduce this issue > I will now move on to trying with git-sources.
As you understand it is hard to narrow down this problem cause 2.6.18 and 2.6.25/26 have huge code differences. It would be nice if you could try as many stable kernels as you can in order to find which kernel causes this issue So some info like latest working kernel: earliest failing kernel: you be much appreciated Thanks :)
(In reply to comment #11) > As you understand it is hard to narrow down this problem cause 2.6.18 and > 2.6.25/26 have huge code differences. It would be nice if you could try as many > stable kernels as you can in order to find which kernel causes this issue > > So some info like > > latest working kernel: > earliest failing kernel: > > you be much appreciated > > Thanks :) > I tried kernel-2.6.28-rc-8-git4: The problem is still there. I will attach the .config for this kernel. Currently there is a big gap for the kernel problem: Last one to work: 2.6.18-gentoo-r6 First one to fail: 2.6.25-gentoo-r7 I will try to narrow this down. Can you suggest which versions I should begin experimenting with? I think following observations might be relevant (I have mentioned some of them also in previous messages): 1. If the new print job is given before the printer has stopped printing there is no problem. Printing will continue with no pause. 2. Previous applies also to 2.6.18-gentoo-r6. 3. With 2.6.18-gentoo-r6 printing will resume after a long pause (about 20 seconds) if the printer has already stopped. I wonder if 2.6.18-gentoo-r6 does some kind of usb scan similar to lsusb -v once in a while and the real problem is present already in this kernel version or that the problem is elsewhere and this older kernel happens to make it more or less invisible? I think there was a time when printing started always almost immediately but I do not have any idea when this might have changed. Maybe is should try some even older kernel versions? The first 2.6-kernel on my hd is linux-2.6.11-gentoo-r8 and the portage tree has an ebuild for gentoo-sources-2.6.16-r13 Is there some other package that would be a probable source for this kind of problem I should try experimenting with?
Created an attachment (id=175714) [details] .config for kernel 2.6.28-rc8-git4
My gentoo version is 2008.0 (not 2006.1 as I had marked in the bug report)
There are not many versions on portage before 2.6.25. So you could try 2.6.20-r10 and 2.6.24-r8. Assuming it is a kernel issue , we could take a look at USB kernel configuration. Daniel is more expert than me on this subsection so he might have some specific ideas. Since then try to enable OHCI support on your new kernel. I am out of ideas right now. I hope that testing 2.6.20,24 kernel will help us more Happy debugging ;)
Could you please post a dmesg output after the first printing (or when you are trying to do the second printing ) ,so we can see if there are any error messages ? Thanks :)
Created an attachment (id=175715) [details] Output from dmesg after print attempt
(In reply to comment #17) > Created an attachment (id=175715) [edit] [details] > Output from dmesg after print attempt > Hi again. I also tried: diff dmesg_after_lsusb_v dmesg_after_trying_to_print No difference here.
(In reply to comment #15) > There are not many versions on portage before 2.6.25. So you could try > 2.6.20-r10 and 2.6.24-r8. Assuming it is a kernel issue , we could take a look > at USB kernel configuration. Daniel is more expert than me on this subsection > so he might have some specific ideas. Since then try to enable OHCI support on > your new kernel. Did not make any difference in behaviour. > > I am out of ideas right now. I hope that testing 2.6.20,24 kernel will help us > more > > Happy debugging ;) > Thanks. Happy debugging will stop any minute now when my wife returns home. Some people just do not see the beauty of compiling kernels all day long :)
(In reply to comment #19) > (In reply to comment #15) > > There are not many versions on portage before 2.6.25. So you could try > > 2.6.20-r10 and 2.6.24-r8. Assuming it is a kernel issue , we could take a look > > at USB kernel configuration. Daniel is more expert than me on this subsection > > so he might have some specific ideas. Since then try to enable OHCI support on > > your new kernel. > > Did not make any difference in behaviour. I assume you mean the OHCI part. Ok , so lets wait until you test those two kernels :)
(In reply to comment #20) > (In reply to comment #19) > > (In reply to comment #15) > > > There are not many versions on portage before 2.6.25. So you could try > > > 2.6.20-r10 and 2.6.24-r8. Assuming it is a kernel issue , we could take a look > > > at USB kernel configuration. Daniel is more expert than me on this subsection > > > so he might have some specific ideas. Since then try to enable OHCI support on > > > your new kernel. > > > > Did not make any difference in behaviour. > > I assume you mean the OHCI part. > > Ok , so lets wait until you test those two kernels :) > Yes. I mean't the OHCI part. I tested the two kernels: 2.6.20-r10 works. 2.6.24-r8 has the problem. I will also attach the configuration files for these kernels. Thank you Markos and Sergei for your effort. I have to return to the non-virtual world for tonight :)
Created an attachment (id=175729) [details] linux-2.6.20-gentoo-r10 .config
Created an attachment (id=175730) [details] linux-2.6.24-gentoo-r8 .config
This has nothing to do with solving the real problem, only something to get it working for me now: Create /usr/sbin/lsusb_script: #!/bin/bash echo "lsusb_script will run 'lsusb -v' every 10 seconds due to usb printing problem." while [ 1 ] do /usr/sbin/lsusb -v > /dev/null sleep 10 done And add the following line to /etc/conf.d/local.start/ lsusb_script &
Created an attachment (id=175909) [details] usblp.patch file Having searched over the Internet, it seems that this problem occurs due to drivers/usb/class/usblp.c code changes A way to verify that, is to apply the attached patch on your working kernel ( 2.6.20-r10 ). When you apply that, recompile the kernel. If I am correct, your printer should stop work :)
I tried to install the patch but compilation failed. I am not familiar with patching so please give me detailed instructions if I did something wrong there. This is what I did and got so far: hiiru class # patch usblp.c usblp.patch hiiru linux-2.6.20-gentoo-r10 # make && make modules_install CHK include/linux/version.h CHK include/linux/utsrelease.h CHK include/linux/compile.h CC drivers/usb/class/usblp.o drivers/usb/class/usblp.c:144: error: field ‘urbs’ has incomplete type drivers/usb/class/usblp.c: In function ‘usblp_unlink_urbs’: drivers/usb/class/usblp.c:453: warning: implicit declaration of function ‘usb_kill_anchored_urbs’ drivers/usb/class/usblp.c: In function ‘usblp_new_writeurb’: drivers/usb/class/usblp.c:706: error: ‘URB_FREE_BUFFER’ undeclared (first use in this function) drivers/usb/class/usblp.c:706: error: (Each undeclared identifier is reported only once drivers/usb/class/usblp.c:706: error: for each function it appears in.) drivers/usb/class/usblp.c: In function ‘usblp_write’: drivers/usb/class/usblp.c:736: warning: implicit declaration of function ‘usb_anchor_urb’ drivers/usb/class/usblp.c:794: warning: implicit declaration of function ‘usb_unanchor_urb’ drivers/usb/class/usblp.c: In function ‘usblp_probe’: drivers/usb/class/usblp.c:1095: warning: implicit declaration of function ‘init_usb_anchor’ make[3]: *** [drivers/usb/class/usblp.o] Error 1 make[2]: *** [drivers/usb/class] Error 2 make[1]: *** [drivers/usb] Error 2 make: *** [drivers] Error 2
Hello there, it would be really helpful if you could provide us with a usbmon trace of both kernels (as the faulty kernel use the latest 2.6.27) while printing. If you don't know how to do that, just follow these steps: 1) Enable CONFIG_DEBUG_FS, CONFIG_USB_DEBUG and CONFIG_USB_MON in your kernels. 2) Follow the easy step-by-step instructions of Documentation/usb/usbmon.txt. 3) When you reach the fourth step of the instructions, start a print job. (Don't forget to do the whole 'lsusb -v' routine when you do it on the faulty kernel.) 4) Stop dumping. 5) Post both dumps here. 6) ??? 7) Profit! (The patch that Markos attached seems to cause compilation errors, indeed, btw.) Thank you :)
(In reply to comment #27) > Hello there, > > it would be really helpful if you could provide us with a usbmon trace > of both kernels (as the faulty kernel use the latest 2.6.27) while printing. > > If you don't know how to do that, just follow these steps: > > 1) Enable CONFIG_DEBUG_FS, CONFIG_USB_DEBUG and CONFIG_USB_MON in your kernels. > 2) Follow the easy step-by-step instructions of Documentation/usb/usbmon.txt. > 3) When you reach the fourth step of the instructions, start a print > job. (Don't forget to do the whole 'lsusb -v' routine when you do it on > the faulty kernel.) > 4) Stop dumping. > 5) Post both dumps here. > 6) ??? > 7) Profit! > > (The patch that Markos attached seems to cause compilation errors, > indeed, btw.) > > Thank you :) > Hi I will now attach the output for kernel 2.6.27-gentoo-r6. I have it in three parts that were generated as follows: # Start monitoring to 1.mon.out and print first job cat /sys/kernel/debug/usbmon/3u > /scratch/tuomas/report/1.mon.out lp -d gimp-printer scratch/test.ps # The first job is printed successfully and printer has stopped printing. # Stop monitoring with Ctrl-C # Start monitoring to 2.mon.out cat /sys/kernel/debug/usbmon/3u > /scratch/tuomas/report/2.mon.out lp -d gimp-printer scratch/test.ps # Nothing is printed. # Stop monitoring with Ctrl-C # Start monitoring to 3.mon.out cat /sys/kernel/debug/usbmon/3u > /scratch/tuomas/report/3.mon.out # Run lsusb -v and printing begins lsusb -v # When printing has stopped stop monitoring to 3.mon.out
Created an attachment (id=176035) [details] usb monitor output for 1st print job on 2.6.27-gentoo-r6
Created an attachment (id=176036) [details] usb monitor output for 2nd print job on 2.6.27-gentoo-r6
Created an attachment (id=176037) [details] usb monitor output for lsusb -v after 2nd print job on 2.6.27-gentoo-r6
Created an attachment (id=176039) [details] usb monitor output for 1st print job on 2.6.20-gentoo-r10
Created an attachment (id=176041) [details] usb monitor output for 2nd print job on 2.6.20-gentoo-r10
Created an attachment (id=176043) [details] usb monitor output for lsusb -v after all printing has finished on 2.6.20-gentoo-r10
Here is some additional output for 2.6.20-gentoo-r10 from cat /sys/kernel/debug/usbmon/3t I added some comments to mark when things actually happened and cut-and-pasted the contents of the terminal. # lp command is given c1700b40 3637679502 S Bi:004:02 -115 8192 < d38972c0 3637679538 S Ci:004:00 s a1 00 0000 0000 03ff 1023 < c1700b40 3637681200 C Bi:004:02 0 0 d38972c0 3637682157 C Ci:004:00 0 109 = 006d4d46 473a4361 6e6f6e3b 434d443a 424a4c2c 424a5261 73746572 332c4253 c1700c40 3638475655 S Bo:004:01 -115 1024 = 1b5b4b02 00000f1b 28610100 011b2862 0100011b 28710100 011b2864 04000168 # Now nothing happens for about 30 secs d3897cc0 3658462516 S Ci:004:00 s a1 01 0000 0000 0001 1 < d3897cc0 3658463633 C Ci:004:00 0 1 = 18 c1700c40 3658515599 C Bo:004:01 0 1024 > c1700c40 3658515913 S Bo:004:01 -115 8192 = ca000d1d bedd57ff ffbf56f7 ff6aff5a a0b1000a 55bfffb7 dbaaffff f6c080d8 c1700c40 3658523618 C Bo:004:01 0 8192 > c1700c40 3658526568 S Bo:004:01 -115 8192 = 000010f7 000080f0 00030100 0008f700 0040ef00 02800004 f3000d1b 28650200 c1700c40 3658534599 C Bo:004:01 0 8192 > c1700c40 3658535945 S Bo:004:01 -115 8192 = e2000020 eb000d1b 28650200 00011b28 4165004b e8001e01 3b8002bb 00007680 c1700c40 3658543594 C Bo:004:01 0 8192 > c1700c40 3658543666 S Bo:004:01 -115 8192 = 54050904 44050804 002284a0 408a2291 52482424 a2085208 202228a5 50120014 c1700c40 3658551583 C Bo:004:01 0 8192 > c1700c40 3658551649 S Bo:004:01 -115 8192 = 54002b6a 92b6dac2 5554d252 aa80daa0 55000a95 0012a04a 0400d925 01a0040d c1700c40 3658559584 C Bo:004:01 0 8192 > c1700c40 3658570527 S Bo:004:01 -115 8192 = 5a5adbbb 6655bb28 0555662a cad76ed5 b55ad1ad 5a59a56a aea55b55 a5a956ab c1700c40 3658578572 C Bo:004:01 0 8192 > c1700c40 3658578697 S Bo:004:01 -115 8192 = bead6d5b bebdb55e b6ab55b6 ab55aeab bbaeb7db 5ed77556 b5bbab6d dbedaab6 c1700c40 3658586568 C Bo:004:01 0 8192 > c1700c40 3658594520 S Bo:004:01 -115 8192 = 0576ae20 577f00eb 56802000 00200000 08000004 00100110 00008000 08fe0003 c1700c40 3658602550 C Bo:004:01 0 8192 > # I removed many lines of output here c1700c40 3660586402 S Bo:004:01 -115 1024 = 3c0c3800 b081009a 000d1b28 65020000 011b2841 27004b9f 001ed400 000fffd8 c1700c40 3660611039 C Bo:004:01 0 1024 > c1700c40 3660613546 S Bo:004:01 -115 1024 = 02400000 20002240 44008000 0001fe00 19441200 40000008 00480100 02400040 c1700c40 3660615025 C Bo:004:01 0 1024 > c1700c40 3660615052 S Bo:004:01 -115 1024 = 002080fe 000c8880 04082000 00888100 010001fe 00041000 100088fe 00040402 c1700c40 3660616023 C Bo:004:01 0 1024 > c1700c40 3660644105 S Bo:004:01 -115 1024 = 00040010 02000004 fd000110 90fd0015 02000080 00411000 20088000 02110002 c1700c40 3660646006 C Bo:004:01 0 1024 > c1700c40 3660647317 S Bo:004:01 -115 1024 = 4bde0000 10fb0000 80f90000 08fc0000 80fa0000 02f80001 0240fc00 0008fd00 c1700c40 3660649007 C Bo:004:01 0 1024 > c1700c40 3660676809 S Bo:004:01 -115 1024 = 00000804 00204000 80000800 00080481 00a5000d 1b286502 0000011b 28416a00 c1700c40 3660677986 C Bo:004:01 0 1024 > c1700c40 3660735537 S Bo:004:01 -115 1024 = 08fd0000 04fe000e 10000100 00100080 00280000 100004f8 000008fe 00010281 c1700c40 3660736936 C Bo:004:01 0 1024 > c1700c40 3660736963 S Bo:004:01 -115 1024 = fe001c40 00000100 00210080 02000200 01000020 01001001 00004000 00010040 c1700c40 3660737934 C Bo:004:01 0 1024 > c1700c40 3660897895 S Bo:004:01 -115 333 = 10044400 0104fe00 02080044 fe000580 00000800 04fe000d 04088108 00004000 c1700c40 3660899833 C Bo:004:01 0 333 > c1700c40 3660913888 S Bo:004:01 -115 2 = 1b40 c1700c40 3660915807 C Bo:004:01 0 2 > # Printing has started # Printing has finished
And here is some additional output for 2.6.27-gentoo-r6 from cat /sys/kernel/debug/usbmon/3u with comments # Print first job da556100 78387641 S Bi:3:002:2 -115 1024 < da556180 78387798 S Ci:3:002:0 s a1 00 0000 0000 03ff 1023 < da556100 78389619 C Bi:3:002:2 0 0 da556180 78390599 C Ci:3:002:0 0 109 = 006d4d46 473a4361 6e6f6e3b 434d443a 424a4c2c 424a5261 73746572 332c4253 da556180 80397402 S Bo:3:002:1 -115 4096 = 1b5b4b02 00000f1b 28610100 011b2862 0100011b 28710100 011b2864 04000168 da556180 80452245 C Bo:3:002:1 0 4096 > # Removed many many lines of output here da556180 82137138 C Bo:3:002:1 0 8192 > da556180 82137232 S Bo:3:002:1 -115 8192 = 680000e0 6003c1c1 a0380078 7801c000 2e0a3c00 001800f0 700c1e00 5087000d da556180 82230075 C Bo:3:002:1 0 8192 > da556180 82230199 S Bo:3:002:1 -115 8192 = 00e0c0fa 00050a02 8000001c 81009700 0d1b2865 02000001 1b284115 004b9c00 da556180 82348991 C Bo:3:002:1 0 8192 > da556180 82349046 S Bo:3:002:1 -115 1359 = fe001c40 00000100 00210080 02000200 01000020 01001001 00004000 00010040 da556180 82363974 C Bo:3:002:1 0 1359 > # Printing has started # Now I will try another job da556700 157950474 S Bi:3:002:2 -115 1024 < da556700 157951795 C Bi:3:002:2 0 0 da556700 157951904 S Ci:3:002:0 s a1 00 0000 0000 03ff 1023 < da556700 157953789 C Ci:3:002:0 0 109 = 006d4d46 473a4361 6e6f6e3b 434d443a 424a4c2c 424a5261 73746572 332c4253 da556200 158777282 S Bo:3:002:1 -115 4096 = 1b5b4b02 00000f1b 28610100 011b2862 0100011b 28710100 011b2864 04000168 # Nothing happens ... # ... still nothing. I will now run lsusb -v da556680 303982561 S Ci:3:002:0 s 80 06 0300 0000 00ff 255 < da556680 303984848 C Ci:3:002:0 0 4 = 04030904 da556680 303984891 S Ci:3:002:0 s 80 06 0301 0409 00ff 255 < da556680 303986847 C Ci:3:002:0 0 12 = 0c034300 61006e00 6f006e00 da556680 303986912 S Ci:3:002:0 s 80 06 0300 0000 00ff 255 < da556680 303988845 C Ci:3:002:0 0 4 = 04030904 da556680 303988885 S Ci:3:002:0 s 80 06 0302 0409 00ff 255 < da556680 303990843 C Ci:3:002:0 0 18 = 12034200 4a004300 2d003300 30003000 3000 da556680 303990892 S Ci:3:002:0 s 80 06 0300 0000 00ff 255 < da556680 303992842 C Ci:3:002:0 0 4 = 04030904 da556680 303992883 S Ci:3:002:0 s 80 06 0303 0409 00ff 255 < da556680 303994840 C Ci:3:002:0 0 14 = 0e033600 42004700 43007300 6500 da556680 303995062 S Ci:3:002:0 s 80 00 0000 0000 0002 2 < da556680 303995841 C Ci:3:002:0 0 2 = 0100 da556680 303995956 S Ci:3:001:0 s 80 06 0300 0000 00ff 255 < # Removed many many lines of output here da556200 305527909 S Bo:3:002:1 -115 8192 = 680000e0 6003c1c1 a0380078 7801c000 2e0a3c00 001800f0 700c1e00 5087000d da556200 305619783 C Bo:3:002:1 0 8192 > da556200 305619849 S Bo:3:002:1 -115 8192 = 00e0c0fa 00050a02 8000001c 81009700 0d1b2865 02000001 1b284115 004b9c00 da556200 305738704 C Bo:3:002:1 0 8192 > da556200 305738796 S Bo:3:002:1 -115 1359 = fe001c40 00000100 00210080 02000200 01000020 01001001 00004000 00010040 da556200 305753677 C Bo:3:002:1 0 1359 > # Printing has now started # And finished also successfully # Lets make another lsusb -v just to see what it does da556780 386305309 S Ci:3:002:0 s 80 06 0300 0000 00ff 255 < da556780 386308202 C Ci:3:002:0 0 4 = 04030904 da556780 386308215 S Ci:3:002:0 s 80 06 0301 0409 00ff 255 < da556780 386310200 C Ci:3:002:0 0 12 = 0c034300 61006e00 6f006e00 da556780 386310471 S Ci:3:002:0 s 80 06 0300 0000 00ff 255 < da556780 386312198 C Ci:3:002:0 0 4 = 04030904 da556780 386312207 S Ci:3:002:0 s 80 06 0302 0409 00ff 255 < da556780 386314197 C Ci:3:002:0 0 18 = 12034200 4a004300 2d003300 30003000 3000 da556780 386314206 S Ci:3:002:0 s 80 06 0300 0000 00ff 255 < da556780 386316195 C Ci:3:002:0 0 4 = 04030904 da556780 386316203 S Ci:3:002:0 s 80 06 0303 0409 00ff 255 < da556780 386318194 C Ci:3:002:0 0 14 = 0e033600 42004700 43007300 6500 da556780 386318383 S Ci:3:002:0 s 80 00 0000 0000 0002 2 < da556780 386319194 C Ci:3:002:0 0 2 = 0100 da556780 386319286 S Ci:3:001:0 s 80 06 0300 0000 00ff 255 < da556780 386319288 C Ci:3:001:0 0 4 = 04030904 da556780 386319291 S Ci:3:001:0 s 80 06 0303 0409 00ff 255 < da556780 386319294 C Ci:3:001:0 0 65 = 40034c00 69006e00 75007800 20003200 2e003600 2e003200 37002d00 67006500 da556780 386319297 S Ci:3:001:0 s 80 06 0300 0000 00ff 255 < da556780 386319298 C Ci:3:001:0 0 4 = 04030904 da556780 386319300 S Ci:3:001:0 s 80 06 0302 0409 00ff 255 < da556780 386319301 C Ci:3:001:0 0 43 = 2a035500 48004300 49002000 48006f00 73007400 20004300 6f006e00 74007200 da556780 386319303 S Ci:3:001:0 s 80 06 0300 0000 00ff 255 < da556780 386319303 C Ci:3:001:0 0 4 = 04030904 da556780 386319305 S Ci:3:001:0 s 80 06 0301 0409 00ff 255 < da556780 386319306 C Ci:3:001:0 0 27 = 1a033000 30003000 30003a00 30003000 3a003100 64002e00 310000 da556780 386319441 S Ci:3:001:0 s a0 06 2900 0000 000d 13 < da556780 386319443 C Ci:3:001:0 0 13 = 0929020a 00010000 ff000000 00 da556780 386319478 S Ci:3:001:0 s a3 00 0000 0001 0004 4 < da556780 386319482 C Ci:3:001:0 0 4 = 03010000 da556780 386319493 S Ci:3:001:0 s a3 00 0000 0002 0004 4 < da556780 386319497 C Ci:3:001:0 0 4 = 00010000 da556780 386319505 S Ci:3:001:0 s 80 00 0000 0000 0002 2 < da556780 386319506 C Ci:3:001:0 0 2 = 0300
Additional to having "usbmon logs", it might be interesting to get the some more diagnostic output from "usblp.c" itself. Can you do the following on your 2.6.27 sources # sed --in-place -re 's/^#undef DEBUG/#define DEBUG/' drivers/usb/class/usblp.c # make Then install and run the kernel. Attach dmesg output. Thanks
(In reply to comment #37) > Additional to having "usbmon logs", it might be interesting to get the some > more diagnostic output from "usblp.c" itself. > > Can you do the following on your 2.6.27 sources > > # sed --in-place -re 's/^#undef DEBUG/#define DEBUG/' drivers/usb/class/usblp.c > # make > > Then install and run the kernel. Attach dmesg output. > > Thanks > Sure. I will attach dmesg_debug_2.6.27-gentoo-r6 And thank you for the detailed instructions. I appreciate it.
Created an attachment (id=176160) [details] dmesg output with debug messages from usblp.c (2.6.27-gentoo-r6)
Created an attachment (id=176327) [details] usblp.c hang debugging Hello, I noticed these two lines in your 2.6.20 usbmon trace: d3897cc0 3658462516 S Ci:004:00 s a1 01 0000 0000 0001 1 < d3897cc0 3658463633 C Ci:004:00 0 1 = 18 Basically, the first line asks the printer if he has the necessary resources to print (ink, paper) and the second line answers with an "aye". The problem is that I can't find these two lines in your 2.6.27 trace and this made me think that the printer never gets these facts and just waits there idling. Also, notice that the 2.6.27 hangs exactly when it should have asked for that information. The whole transaction described above is started with a GET_PORT_STATUS request, which is implemented by the usblp_read_status macro in drivers/usb/class/usblp.c. I checked for changes in this and related pieces of code and I found that they added mutex locking in function usblp_check_status() and since we are talking about hanging, it wouldn't surprise me if it was caused by a deadlock. So, I made this little patch which adds debugging messages before/after the mutex locking/unlocking and before/after a usb_control_msg() call in usblp_ctrl_msg(), to check whether the hanging happens there. Please patch against a fresh linux-2.6.27.8, try your usual printing routine and then post your dmesg here. Thanks for your patience :)
(In reply to comment #40) > Please patch against a fresh linux-2.6.27.8, try your usual printing routine > and then post your dmesg here. Hi I did not find the version number you requested in the list available gentoo-sources. Please specify which version of the kernel should I emerge? This is the list of gentoo-sources I have in my portage tree. gentoo-sources-2.6.16-r13.ebuild gentoo-sources-2.6.20-r10.ebuild gentoo-sources-2.6.24-r8.ebuild gentoo-sources-2.6.25-r9.ebuild gentoo-sources-2.6.26-r2.ebuild gentoo-sources-2.6.26-r3.ebuild gentoo-sources-2.6.26-r4.ebuild gentoo-sources-2.6.27.ebuild gentoo-sources-2.6.27-r1.ebuild gentoo-sources-2.6.27-r2.ebuild gentoo-sources-2.6.27-r3.ebuild gentoo-sources-2.6.27-r4.ebuild gentoo-sources-2.6.27-r5.ebuild gentoo-sources-2.6.27-r6.ebuild gentoo-sources-2.6.27-r7.ebuild gentoo-sources-2.6.28.ebuild Thanks
(In reply to comment #41) > I did not find the version number you requested in the list available > gentoo-sources. Please specify which version of the kernel should I emerge? please use vanilla-sources-2.6.27.8
Created an attachment (id=176668) [details] dmesg output with usb hang debug patch applied Hi I applied the patch in the previous attachment and ran: lp -d gimp-printer test.ps lp -d gimp-printer test.ps lsusb -v dmesg > dmesg_for_usblp_hang_patch I also did the following test to see what happens and when. There does not seem to be hanging inside usblp_ctrl_msg(). Actual printing of both jobs happened only after the lsusb -v command. hiiru scratch # dmesg -c > dmesg.0 hiiru scratch # dmesg hiiru scratch # lp -d gimp-printer test.ps request id is gimp-printer-880 (1 file(s)) hiiru scratch # dmesg usblp0: in usblp_ctrl_msg: executing usb_control_msg usblp0: in usblp_ctrl_msg: finished executing usb_control_msg hiiru scratch # lp -d gimp-printer test.ps request id is gimp-printer-881 (1 file(s)) hiiru scratch # dmesg usblp0: in usblp_ctrl_msg: executing usb_control_msg usblp0: in usblp_ctrl_msg: finished executing usb_control_msg hiiru scratch # lsusb -v > /dev/null hiiru scratch # dmesg usblp0: in usblp_ctrl_msg: executing usb_control_msg usblp0: in usblp_ctrl_msg: finished executing usb_control_msg usblp0: in usblp_ctrl_msg: executing usb_control_msg usblp0: in usblp_ctrl_msg: finished executing usb_control_msg hiiru scratch # I just keep wondering. If this is a common problem with many usb connected printers there should be a huge amount of bug reports and discussion on the forums about it. I guess that even the Canon BJC-3000 is not a very uncommon printer. If there is someone out there who has a Canon BJC-3000 and is printing happily with a somewhat up-to-date kernel I would very much like to try out his/her kernel configuration. Well I guess this bug report is probably not the best forum to reach the masses :)
Created an attachment (id=176826) [details] yet another patch adding debug messages Hello there again, it seems like the problem wasn't in usblp_check_status() (as a matter of fact, usblp_check_status() doesn't ever seem to be called). I made another patch and added debug messages in some other suspicious functions (usblp_wwait() got many changes since 2.6.20 and they also introduced locking in it.) Patch against a vanilla-sources-2.6.27.8 kernel, do your printing routine and send us back the dmesg log. By the way, I noticed that the first printing of a 2.6.20 kernel doesn't request a GET_PORT_STATUS while the second does. I'm wondering why does this happen. Thank you :)
Created an attachment (id=176907) [details] dmesg output for papatch Hi I applied only papatch. Should I also apply the usb_hang_debug_patch? I made following observations that I suppose suggest that the hanging happens at the printer end of the usb cable. I left an print job hanging (= Did not launch it with lsusb -v) and Rebooted my computer -> No printing happened Rebooted my computer so that the power was off for a while (front panel switch only, not the actual power switch) -> No printing happened. Same as previous + Switched printer off and on while computer power was off. -> The job was printed when cupsd started. It seems that someone creates or sends some command to the printer that causes it to appear busy or to suspend somehow? Could it be that the old kernel versions were not as patient as the newer versions and did something to wake up the printer when they timed out or did some polling that caused stuck devices to continue (like lsusb -v) or did some kind of extra reset sequence before new data is send? As I mentioned the wait until the printing of "the second job" is quite long on the older kernels. Some kind of illegal data or control data at the end of print jobs would explain it, but two jobs will get printed if the second one is submitted before the first one has stopped. This does not support the theory that the data is corrupt? I was just wondering about the question about GET_PORT_STATUS. If the printer or some piece of software reports the status incorrectly (reports busy when actually could accept data). Could this be tested by hard coding some appropriate function to return always ok and ignore possible busy messages? I am not at all familiar with the relevant code or even how usb communications is organized, so please forgive me for speculating about something I really know nothing about :) Thanks
(In reply to comment #45) > I applied only papatch. Should I also apply the usb_hang_debug_patch? Yep, papatch included usb_hang_debug_patch in it as well. I marked the latter as obsolete. > I made following observations that I suppose suggest that the hanging happens > at the printer end of the usb cable. I left an print job hanging (= Did not > launch it with lsusb -v) and > It seems that someone creates or sends some command to the printer that causes > it to appear busy or to suspend somehow? Could it be that the old kernel > versions were not as patient as the newer versions and did something to wake up > the printer when they timed out or did some polling that caused stuck devices > to continue (like lsusb -v) or did some kind of extra reset sequence before new > data is send? As I mentioned the wait until the printing of "the second job" is > quite long on the older kernels. Sorry for being pigheaded with my GET_PORT_STATUS claim, but I'd like to mention again that EXACTLY after the wait of the printing of 'the second job' ends, the two abovementioned GET_PORT_STATUS request lines get printed in the usbmon log, which makes me believe that the the driver was waiting for the printer's status all along these 30 seconds and went ahead on printing when he got the 'approval flag' from the printer: ---------- 2.6.20 usbmon log with Tuomas' comments (comment 35) ---------- # Now nothing happens for about 30 secs d3897cc0 3658462516 S Ci:004:00 s a1 01 0000 0000 0001 1 < d3897cc0 3658463633 C Ci:004:00 0 1 = 18 ---------- 2.6.20 usbmon log with Tuomas' comments (comment 35) ---------- > I was just wondering about the question about GET_PORT_STATUS. If the printer > or some piece of software reports the status incorrectly (reports busy when > actually could accept data). Could this be tested by hard coding some > appropriate function to return always ok and ignore possible busy messages? Actually, from what I see the driver never requests the status of the printer in 2.6.27 in the first place (in 2.6.20 when the driver got the status answer from the printer it moved on to printing the second job, as can be seen in comment 35) What would be interesting is isolating the function that calls usblp_read_status in the 2.6.20 kernel and finding out why it isn't called in 2.6.27, but I'm starting to get a bit afraid that this whole GET_PORT_STATUS paranoia will not be the problem in the end.
Thanks for all the info. Indeed, your printer seems to "hang" (it stops acknowledging data that the computer has sent it) after 1 print job, until it has been prodded on the control pipe (which happens when you do lsusb -v, or after a 20 second timeout on the old kernel). Do you happen to have easy access to getting this printer running on windows 2000 or XP? I would be interested in comparing the USB traffic from canon's own driver, but don't worry if it's a problem...
(In reply to comment #47) > Thanks for all the info. Indeed, your printer seems to "hang" (it stops > acknowledging data that the computer has sent it) after 1 print job, until it > has been prodded on the control pipe (which happens when you do lsusb -v, or > after a 20 second timeout on the old kernel). > > Do you happen to have easy access to getting this printer running on windows > 2000 or XP? I would be interested in comparing the USB traffic from canon's own > driver, but don't worry if it's a problem... > Hi I have Vista running on a different PC. The problem does not seem to be present under Vista. Printing starts quite promptly after the command is given. For getting some debug information out of Vista and it's printer driver I would need some instructions. Thanks
See http://www.reactivated.net/fprint/wiki/USB_sniffing which is mostly appropriate here. I have not used the HHD sniffer listed there, but hopefully you will be able to read the SniffUsb instructions and figure out how to do the equivalent under HHD. Then capture a session as follows: 1. turn on printer 2. wait 5 secs 3. attempt to reproduce the Linux bug, i.e. start 2 print jobs(?) or however you would do it 4. stop logger after printing of the 2nd page has finished And then please upload the logs here.
Created an attachment (id=177124) [details] An exported session of Device Monitoring Studio, Packet View Hi Here is some output from Device Monitoring Studio probably from only one print job. I will also attach a log file that it created. I do not know if the format of the log file can be opened anywhere outside the Device Monitoring Studio. I can try to familiarize myself with the software and try to export something else also if this is not at all usable.
Created an attachment (id=177126) [details] Log file from Device Monitoring Support
No, that isn't useful, unfortunately. Is that from HHD? I believe there should be some kind of "export to text" or html functionality in there somewhere.
Created an attachment (id=177145) [details] HHD SOftware Device Monitoring Studio output for 2 print jobs Sorry about the messed up log files. The new attachment makes probably a little bit more sense. The software I am using is a trial version of HHD SOftware Device Monitoring Studio. Line 00182 starts the second print job according to time stamp. The printer seems to report its vendor etc. information many times. Does it mean that the driver resets/polls/whatever always when it starts or stops doing something just in-case it might be needed? The printer reports it's name over 60 times when printing two pages :) If the Linux implementation works with all other printers, I guess Canon BJC-3000 does not work quite according to some specification it should follow and needs some extra resetting to work reliably? If this is the case should and could it be handled like other printer quirks by usblp.c or is it rather a printer driver issue?
The windows driver is polling for the information every second -- on the control pipe, (sort of) equivalent of you running "lsusb" Strange, but seems like a good confirmation of this "bug", and an option we have for avoiding it. I sent a mail upstream to get some feedback.
upstream discussion http://article.gmane.org/gmane.linux.usb.general/13527
Seeing that Pete Zaitcev coded a patch possibly fixing your problem, could you, Tuomas, try it out? Patch below: http://article.gmane.org/gmane.linux.usb.general/13540
(In reply to comment #56) > Seeing that Pete Zaitcev coded a patch possibly fixing your problem, could you, > Tuomas, try it out? > > Patch below: > http://article.gmane.org/gmane.linux.usb.general/13540 > Yep. I patched against linux-2.6.27.8 and tried printing with my old test file. Everything worked fine. I will keep the configuration and report later if something odd occurs. The solution seems such, that it seems unlikely that surprises would emerge later. Thank you all very much for your great effort on solving the problem.
Thanks, I reported the success upstream. Will wait for the patch to get submitted properly, then we will include it.
This has made Linus' tree
Released in gentoo-sources-2.6.29-r3
