ulpt or ohci bug [was: Proposed patch to ulpt.c]

[Panagiotis Astithas]

I have been experiencing problems with a Hewlett-Packard Color LaserJet 
2550 series printer, so I tried your patch. I had to manually remove the 
local declaration of 'spin', since buildkernel failed. For my situation 
things remain the same, i.e. nothing breaks, but I still get the 
symptoms I will describe next. So, at least this is a 'it doesn't break 
anything' message.


I have been reading the relevant code, but I can't see whether my 
problem is in ulpt or ohci. If someone who knows this stuff can lead me 
to the right direction, it would be very much appreciated. I've even 
tried an interesting patch from NetBSD (ulpt.c, rev. 1.64) but it didn't 
help either.

My long-standing problem with ulpt (and RELENG_5) is that printing 
(through cups or lpd) always works for the first document, but the next 
process hangs forever in a ulptwr state:

box# ps axwwwl | grep usb
     0    45     0   0   8  0     0     8 usbevt DL    ??    0:00.02 [usb0]
     0    46     0   0   8  0     0     8 usbtsk DL    ??    0:00.00 
[usbtask]
     0    47     0   0   8  0     0     8 usbevt DL    ??    0:00.00 [usb1]
     0   368     1   0  96  0  1244   768 select Is    ??    0:00.01 
/usr/sbin/usbd
     0   735   479   0   0  0  2572  1332 ulptwr I     ??    0:00.01 
usb:/dev/ulpt0 11 root Test Page 1 (usb)
     0   794   480   0  96  0   352   220 -      R+    p0    0:00.00 
grep usb
     0   773   771   0   5  0  1696  1348 ttyin  I+    p1    0:00.13 
less usb.debug


I see the same behavior on two different systems, on 5.4, RELENG_5, SMP 
and UP. This particular system has:

box# usbdevs -v
Controller /dev/usb0:
addr 1: full speed, self powered, config 1, OHCI root hub(0x0000), 
SiS(0x0000), rev 1.00
  port 1 addr 2: full speed, power 2 mA, config 1, hp color LaserJet 
2550 series(0x1c17), Hewlett-Packard(0x03f0), rev 1.00
  port 2 powered
  port 3 powered
Controller /dev/usb1:
addr 1: full speed, self powered, config 1, OHCI root hub(0x0000), 
SiS(0x0000), rev 1.00
  port 1 powered
  port 2 powered
  port 3 powered




Jul 11 16:10:46 box kernel: ohci0: <SiS 5571 USB controller> mem 
0xe7000000-0xe7
000fff irq 20 at device 3.0 on pci0
Jul 11 16:10:46 box kernel: usb0: OHCI version 1.0, legacy support
Jul 11 16:10:46 box kernel: usb0: <SiS 5571 USB controller> on ohci0
Jul 11 16:10:46 box kernel: usb0: USB revision 1.0
Jul 11 16:10:46 box kernel: uhub0: SiS OHCI root hub, class 9/0, rev 
1.00/1.00,
addr 1
Jul 11 16:10:46 box kernel: uhub0: 3 ports with 3 removable, self powered
Jul 11 16:10:46 box kernel: ohci1: <SiS 5571 USB controller> mem 
0xe6800000-0xe6
800fff irq 21 at device 3.1 on pci0
Jul 11 16:10:46 box kernel: usb1: OHCI version 1.0, legacy support
Jul 11 16:10:46 box kernel: usb1: <SiS 5571 USB controller> on ohci1
Jul 11 16:10:46 box kernel: usb1: USB revision 1.0
Jul 11 16:10:46 box kernel: uhub1: SiS OHCI root hub, class 9/0, rev 
1.00/1.00,
addr 1
Jul 11 16:10:46 box kernel: uhub1: 3 ports with 3 removable, self powered
Jul 11 16:10:46 box kernel: pci0: <serial bus, USB> at device 3.3 (no 
driver att
ached)
Jul 11 16:10:46 box kernel: ulpt0: Hewlett-Packard hp color LaserJet 
2550 series
, rev 2.00/1.00, addr 2, iclass 7/1
Jul 11 16:10:46 box kernel: ulpt0: using bi-directional mode



Cranking up hw.usb.ohci.debug and hw.usb.ulpt.debug to 1 and sending a 
test page from CUPS, I get:

Jul 11 17:26:53 box kernel: ulptopen: flags=0x0
Jul 11 17:26:53 box kernel: ulpt_open: open input pipe
Jul 11 17:26:53 box kernel: ulpt_open: start read callout
Jul 11 17:26:53 box kernel: ulptopen: done, error=0
Jul 11 17:26:53 box kernel: ulptwrite
Jul 11 17:26:53 box kernel: ohci_alloc_std_chain: start len=4096
Jul 11 17:26:53 box kernel: ulptwrite
Jul 11 17:26:53 box kernel: ohci_alloc_std_chain: start len=4096
Jul 11 17:26:54 box last message repeated 3 times
Jul 11 17:26:54 box kernel: ulptwrite
Jul 11 17:26:54 box kernel: ohci_alloc_std_chain: start len=4096
Jul 11 17:26:54 box kernel: ohci_alloc_std_chain: start len=4096
Jul 11 17:26:54 box kernel: ohci_device_bulk_close: pipe=0xc1968400
Jul 11 17:26:54 box kernel: ohci_device_bulk_close: pipe=0xc1735680
Jul 11 17:26:54 box kernel: ulptclose: closed

Sending a second test page gives this:

Jul 11 17:27:43 box kernel: ulptopen: flags=0x0
Jul 11 17:27:43 box kernel: ulpt_open: open input pipe
Jul 11 17:27:43 box kernel: ulpt_open: start read callout
Jul 11 17:27:43 box kernel: ulptopen: done, error=0
Jul 11 17:27:43 box kernel: ulptwrite
Jul 11 17:27:43 box kernel: ohci_alloc_std_chain: start len=4096
Jul 11 17:28:14 box last message repeated 152 times
Jul 11 17:30:15 box last message repeated 605 times
Jul 11 17:40:16 box last message repeated 3005 times
Jul 11 17:48:16 box last message repeated 2402 times
Jul 11 17:48:16 box kernel: ohci_device_bulk_abort: xfer=0xc1987b00
Jul 11 17:48:16 box kernel: ohci_abort_xfer: xfer=0xc1987b00 
pipe=0xc15ba680 sed=0xc1592760
Jul 11 17:48:16 box kernel: ulptwrite: error=18
Jul 11 17:48:16 box kernel: ohci_device_bulk_close: pipe=0xc15ba680
Jul 11 17:48:16 box kernel: ohci_device_bulk_close: pipe=0xc15bab00
Jul 11 17:48:16 box kernel: ulptclose: closed


where after 20 minutes I killed the process. I have a similar but 
lengthier debug output with the same sysctl variables raised to 100, here:

http://www.netmode.ntua.gr/~past/ulpt.debug.gz

If anyone could explain the events a bit and tell me where I should 
concentrate my debugging, I would appreciate it a lot!


Thanks,

Panagiotis