Subject: Re: USB to HP 6200c scanner
To: None <current-users@netbsd.org>
From: Sverre Froyen <sverre@viewmark.com>
List: current-users
Date: 01/02/2003 09:33:47
Here is more debugging information.  I turned on a high level of debug in 
uhci.c and receive the following output:

Good request outputs:

usbd_get_desc: type=1, index=0, len=18
uhci_device_control type=0x80, request=0x06, wValue=0x0100, wIndex=0x0000 
len=18, addr=0, endpt=0
uhci_alloc_std_chain: addr=0 endpt=0 len=18 speed=2 flags=0x2
uhci_alloc_std_chain: maxp=8 ntd=3
uhci_alloc_std_chain: nexttog=0
uhci_device_request: before transfer
TD(0xd2f6efc0) at 0167ffc0 = link=0x0167ff44 status=0x18800000 
token=0x00e0002d buffer=0x01682f80
  167ff44<VF> 18800000<ACTIVE>,errcnt=3,actlen=1 
pid=2d,addr=0,endpt=0,D=0,maxlen=8
TD(0xd2f6ef40) at 0167ff40 = link=0x0167ff64 status=0x188003ff 
token=0x00e80069 buffer=0x01682f40
  167ff64<VF> 188003ff<ACTIVE>,errcnt=3,actlen=0 
pid=69,addr=0,endpt=0,D=1,maxlen=8
TD(0xd2f6ef60) at 0167ff60 = link=0x0167ff84 status=0x188003ff 
token=0x00e00069 buffer=0x01682f48
  167ff84<VF> 188003ff<ACTIVE>,errcnt=3,actlen=0 
pid=69,addr=0,endpt=0,D=0,maxlen=8
TD(0xd2f6ef80) at 0167ff80 = link=0x0167ffa4 status=0x188003ff 
token=0x00280069 buffer=0x01682f50
  167ffa4<VF> 188003ff<ACTIVE>,errcnt=3,actlen=0 
pid=69,addr=0,endpt=0,D=1,maxlen=2
TD(0xd2f6efa0) at 0167ffa0 = link=0x00000001 status=0x19800000 
token=0xffe800e1 buffer=0x00000000
  1<T> 19800000<ACTIVE,IOC>,errcnt=3,actlen=1 
pid=e1,addr=0,endpt=0,D=1,maxlen=0
uhci_add_ctrl: sqh=0xd2f6df60
uhci_enter_ctl_q: follow from [0]
TD(0xd2f6bfc0) at 0167cfc0 = link=0x0167df62 status=0x02000000 
token=0x00000000 buffer=0x00000000
  167df62<Q> 2000000<ISO>,errcnt=0,actlen=1 pid=00,addr=0,endpt=0,D=0,maxlen=1
QH(0xd2f6cf60) at 0167df60: hlink=0167df82 elink=00000001
QH(0xd2f6cf60) at 0167df60: hlink=0167df82 elink=00000001
QH(0xd2f6cf80) at 0167df80: hlink=0167dfa2 elink=00000001
QH(0xd2f6cfc0) at 0167dfc0: hlink=0167dfe2 elink=00000001
QH(0xd2f6cfe0) at 0167dfe0: hlink=00000001 elink=0167cfe0
Enqueued QH:
QH(0xd2f6df60) at 0167ef60: hlink=0167dfc2 elink=0167ffc0
TD(0xd2f6efc0) at 0167ffc0 = link=0x0167ff44 status=0x18800000 
token=0x00e0002d buffer=0x01682f80
  167ff44<VF> 18000007,errcnt=3,actlen=8 pid=2d,addr=0,endpt=0,D=0,maxlen=8
TD(0xd2f6ef40) at 0167ff40 = link=0x0167ff64 status=0x188807ff 
token=0x00e80069 buffer=0x01682f40
  167ff64<VF> 188807ff<NAK,ACTIVE>,errcnt=3,actlen=0 
pid=69,addr=0,endpt=0,D=1,maxlen=8
TD(0xd2f6ef60) at 0167ff60 = link=0x0167ff84 status=0x188003ff 
token=0x00e00069 buffer=0x01682f48
  167ff84<VF> 188003ff<ACTIVE>,errcnt=3,actlen=0 
pid=69,addr=0,endpt=0,D=0,maxlen=8
TD(0xd2f6ef80) at 0167ff80 = link=0x0167ffa4 status=0x188003ff 
token=0x00280069 buffer=0x01682f50
  167ffa4<VF> 188003ff<ACTIVE>,errcnt=3,actlen=0 
pid=69,addr=0,endpt=0,D=1,maxlen=2
TD(0xd2f6efa0) at 0167ffa0 = link=0x00000001 status=0x19800000 
token=0xffe800e1 buffer=0x00000000
  1<T> 19800000<ACTIVE,IOC>,errcnt=3,actlen=1 
pid=e1,addr=0,endpt=0,D=1,maxlen=0
uhci_intr: real interrupt
uhci0: uhci_intr1
uhci0 regs: cmd=0081, sts=0001, intr=000f, frnum=04dd, flbase=0167b374, 
sof=0040, portsc1=0095, portsc2=0080
uhci0: uhci_intr: exit
uhci0: uhci_softintr (0)
uhci_check_intr: ii=0xc08d5a6c
uhci_check_intr: ii=0xc08d5a6c done
uhci_idone: ii=0xc08d5a6c
uhci_idone: ii=0xc08d5a6c, xfer=0xc08d5a00, pipe=0xc0aa0d80 ready
TD(0xd2f6efc0) at 0167ffc0 = link=0x0167ff44 status=0x18000007 
token=0x00e0002d buffer=0x01682f80
  167ff44<VF> 18000007,errcnt=3,actlen=8 pid=2d,addr=0,endpt=0,D=0,maxlen=8
TD(0xd2f6ef40) at 0167ff40 = link=0x0167ff64 status=0x18000007 
token=0x00e80069 buffer=0x01682f40
  167ff64<VF> 18000007,errcnt=3,actlen=8 pid=69,addr=0,endpt=0,D=1,maxlen=8
TD(0xd2f6ef60) at 0167ff60 = link=0x0167ff84 status=0x18000007 
token=0x00e00069 buffer=0x01682f48
  167ff84<VF> 18000007,errcnt=3,actlen=8 pid=69,addr=0,endpt=0,D=0,maxlen=8
TD(0xd2f6ef80) at 0167ff80 = link=0x0167ffa4 status=0x18000001 
token=0x00280069 buffer=0x01682f50
  167ffa4<VF> 18000001,errcnt=3,actlen=2 pid=69,addr=0,endpt=0,D=1,maxlen=2
TD(0xd2f6efa0) at 0167ffa0 = link=0x00000001 status=0x190007ff 
token=0xffe800e1 buffer=0x00000000
  1<T> 190007ff<IOC>,errcnt=3,actlen=0 pid=e1,addr=0,endpt=0,D=1,maxlen=0
uhci_idone: actlen=18, status=0x0
uhci_remove_hs_ctrl: sqh=0xd2f6df60
uhci_find_prev_qh: pqh=0xd2f6cfa0 sqh=0xd2f6df60
uhci_ctrl_done: length=18
uhci_idone: ii=0xc08d5a6c done
usbd_get_desc return status = 0

and bad request produces:

usbd_get_desc: type=1, index=0, len=18
uhci_device_control type=0x80, request=0x06, wValue=0x0100, wIndex=0x0000 
len=18, addr=0, endpt=0
uhci_alloc_std_chain: addr=0 endpt=0 len=18 speed=2 flags=0x2
uhci_alloc_std_chain: maxp=8 ntd=3
uhci_alloc_std_chain: nexttog=0
uhci_device_request: before transfer
TD(0xd2f6efc0) at 0167ffc0 = link=0x0167ff44 status=0x18800000 
token=0x00e0002d buffer=0x01682f80
  167ff44<VF> 18800000<ACTIVE>,errcnt=3,actlen=1 
pid=2d,addr=0,endpt=0,D=0,maxlen=8
TD(0xd2f6ef40) at 0167ff40 = link=0x0167ff64 status=0x188003ff 
token=0x00e80069 buffer=0x01682f40
  167ff64<VF> 188003ff<ACTIVE>,errcnt=3,actlen=0 
pid=69,addr=0,endpt=0,D=1,maxlen=8
TD(0xd2f6ef60) at 0167ff60 = link=0x0167ff84 status=0x188003ff 
token=0x00e00069 buffer=0x01682f48
  167ff84<VF> 188003ff<ACTIVE>,errcnt=3,actlen=0 
pid=69,addr=0,endpt=0,D=0,maxlen=8
TD(0xd2f6ef80) at 0167ff80 = link=0x0167ffa4 status=0x188003ff 
token=0x00280069 buffer=0x01682f50
  167ffa4<VF> 188003ff<ACTIVE>,errcnt=3,actlen=0 
pid=69,addr=0,endpt=0,D=1,maxlen=2
TD(0xd2f6efa0) at 0167ffa0 = link=0x00000001 status=0x19800000 
token=0xffe800e1 buffer=0x00000000
  1<T> 19800000<ACTIVE,IOC>,errcnt=3,actlen=1 
pid=e1,addr=0,endpt=0,D=1,maxlen=0
uhci_add_ctrl: sqh=0xd2f6df60
uhci_enter_ctl_q: follow from [0]
TD(0xd2f6bfc0) at 0167cfc0 = link=0x0167df62 status=0x02000000 
token=0x00000000 buffer=0x00000000
  167df62<Q> 2000000<ISO>,errcnt=0,actlen=1 pid=00,addr=0,endpt=0,D=0,maxlen=1
QH(0xd2f6cf60) at 0167df60: hlink=0167df82 elink=00000001
QH(0xd2f6cf60) at 0167df60: hlink=0167df82 elink=00000001
QH(0xd2f6cf80) at 0167df80: hlink=0167dfa2 elink=00000001
QH(0xd2f6cfc0) at 0167dfc0: hlink=0167dfe2 elink=00000001
QH(0xd2f6cfe0) at 0167dfe0: hlink=00000001 elink=0167cfe0
Enqueued QH:
QH(0xd2f6df60) at 0167ef60: hlink=0167dfc2 elink=0167ffc0
TD(0xd2f6efc0) at 0167ffc0 = link=0x0167ff44 status=0x18800000 
token=0x00e0002d buffer=0x01682f80
  167ff44<VF> 18000007,errcnt=3,actlen=8 pid=2d,addr=0,endpt=0,D=0,maxlen=8
TD(0xd2f6ef40) at 0167ff40 = link=0x0167ff64 status=0x188807ff 
token=0x00e80069 buffer=0x01682f40
  167ff64<VF> 188807ff<NAK,ACTIVE>,errcnt=3,actlen=0 
pid=69,addr=0,endpt=0,D=1,maxlen=8
TD(0xd2f6ef60) at 0167ff60 = link=0x0167ff84 status=0x188003ff 
token=0x00e00069 buffer=0x01682f48
  167ff84<VF> 188003ff<ACTIVE>,errcnt=3,actlen=0 
pid=69,addr=0,endpt=0,D=0,maxlen=8
TD(0xd2f6ef80) at 0167ff80 = link=0x0167ffa4 status=0x188003ff 
token=0x00280069 buffer=0x01682f50
  167ffa4<VF> 188003ff<ACTIVE>,errcnt=3,actlen=0 
pid=69,addr=0,endpt=0,D=1,maxlen=2
TD(0xd2f6efa0) at 0167ffa0 = link=0x00000001 status=0x19800000 
token=0xffe800e1 buffer=0x00000000
  1<T> 19800000<ACTIVE,IOC>,errcnt=3,actlen=1 
pid=e1,addr=0,endpt=0,D=1,maxlen=0
#TIMEOUT HAPPENS HERE
uhci_timeout: uxfer=0xc08d5a00
usb_add_task: task=0xc08d5a84
usb_task_thread: woke up task=0xc08d5a84
uhci_timeout_task: xfer=0xc08d5a00
uhci_abort_xfer: xfer=0xc08d5a00, status=15
uhci_abort_xfer: stop ii=0xc08d5a6c
uhci_abort_xfer: tsleep
uhci0: uhci_softintr (0)
uhci_check_intr: ii=0xc08d5a6c
uhci_check_intr: aborted xfer=0xc08d5a00
uhci_abort_xfer: callback
uhci_remove_hs_ctrl: sqh=0xd2f6df60
uhci_find_prev_qh: pqh=0xd2f6cfa0 sqh=0xd2f6df60
uhci_ctrl_done: length=0
usbd_get_desc return status = 15

they are identical until the timeout occurs.  It looks like a lost interrupt, 
but it happens too regularly to be _just_ that.

I have also attached the output from dmesg, below.

On Tuesday 31 December 2002 19:15, sverre@viewmark.com wrote:
> Hi,
>
> I'm trying to connect an HP 6200c scanner to my laptop. The laptop is
> running current.  When I plug in the USB cable I get a uhci_timeout and the
> port is disabled.
>
> Some debugging shows that this code fragment (added in dev/usb/usb_subr.c)
> succeeds
>
> 	/* Get the first 8 bytes of the device descriptor. */
> 	err = usbd_get_desc(dev, UDESC_DEVICE, 0, 8, dd);
> 	err = usbd_get_desc(dev, UDESC_DEVICE, 0, 8, dd);
>
> whereas following fails with a timeout on the second (18 byte)
> usbd_get_desc command
>
> 	/* Get the first 8 bytes of the device descriptor. */
> 	err = usbd_get_desc(dev, UDESC_DEVICE, 0, 8, dd);
> 	err = usbd_get_desc(dev, UDESC_DEVICE, 0, 18, dd);
>
> Adding another 18 byte usbd_get_desc command succeeds, yet another times
> out, etc.
>
> I have tried adding "repeat until success" at various places in the code,
> but the result is a timeout in some other part of the code.
>
> Ideas?
>
> Sverre
>
> PS The scanner and the laptop works under Windows 2000.

NetBSD 1.6K (ABBOR: GENERIC-$Revision: 1.532 $) #17: Thu Jan  2 09:17:56 MST 
2003
    toor@abbor.fesk.com:/usr/src/sys/arch/i386/compile/ABBOR
total memory = 255 MB
avail memory = 233 MB
using 3296 buffers containing 13184 KB of memory
BIOS32 rev. 0 found at 0xfd82c
PCI BIOS rev. 2.1 found at 0xfd980
PCI IRQ Routing Table rev. 1.0 found at 0xfdf30, size 176 bytes (9 entries)
PCI Interrupt Router at 000:07:0 (vendor 0x8086 product 0x122e)
pci_addr_fixup: 000:10:0 0x104c 0xac51 new address 0x10000000
pci_addr_fixup: 000:10:1 0x104c 0xac51 new address 0x10001000
mainbus0 (root)
cpu0 at mainbus0: (uniprocessor)
cpu0: Intel Pentium III (686-class), 697.04 MHz, id 0x683
cpu0: features 383f9ff<FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,SEP,MTRR>
cpu0: features 383f9ff<PGE,MCA,CMOV,PAT,PSE36,MMX>
cpu0: features 383f9ff<FXSR,SSE>
cpu0: I-cache 16 KB 32b/line 4-way, D-cache 16 KB 32b/line 4-way
cpu0: L2 cache 256 KB 32b/line 8-way
cpu0: ITLB 32 4 KB entries 4-way, 2 4 MB entries fully associative
cpu0: DTLB 64 4 KB entries 4-way, 8 4 MB entries 4-way
cpu0: 8 page colors
pci0 at mainbus0 bus 0: configuration mode 1
pci0: i/o space, memory space enabled, rd/line, rd/mult, wr/inv ok
pchb0 at pci0 dev 0 function 0
pchb0: vendor 0x8086 product 0x7190 (rev. 0x03)
agp0 at pchb0: aperture at 0xf8000000, size 0x4000000
ppb0 at pci0 dev 1 function 0: vendor 0x8086 product 0x7191 (rev. 0x03)
pci1 at ppb0 bus 1
pci1: i/o space, memory space enabled
vga0 at pci1 dev 0 function 0: vendor 0x1002 product 0x4c4d (rev. 0x64)
wsdisplay0 at vga0 kbdmux 1: console (80x25, vt100 emulation)
wsmux1: connecting to wsdisplay0
pcib0 at pci0 dev 7 function 0
pcib0: vendor 0x8086 product 0x7110 (rev. 0x02)
pciide0 at pci0 dev 7 function 1: Intel 82371AB IDE controller (PIIX4) (rev. 
0x01)
pciide0: bus-master DMA support present
pciide0: primary channel wired to compatibility mode
wd0 at pciide0 channel 0 drive 0: <IBM-DJSA-220>
wd0: drive supports 16-sector PIO transfers, LBA addressing
wd0: 17301 MB, 16383 cyl, 16 head, 63 sec, 512 bytes/sect x 35433216 sectors
wd0: 32-bit data port
wd0: drive supports PIO mode 4, DMA mode 2, Ultra-DMA mode 4 (Ultra/66)
pciide0: primary channel interrupting at irq 14
wd0(pciide0:0:0): using PIO mode 4, Ultra-DMA mode 2 (Ultra/33) (using DMA 
data transfers)
pciide0: secondary channel wired to compatibility mode
atapibus0 at pciide0 channel 1: 2 targets
cd0 at atapibus0 drive 0: <TOSHIBA DVD-ROM SD-C2402, 7000008617, 1917> cdrom 
removable
cd0: 32-bit data port
cd0: drive supports PIO mode 4, DMA mode 2
pciide0: secondary channel interrupting at irq 15
cd0(pciide0:1:0): using PIO mode 4, DMA mode 2 (using DMA data transfers)
uhci0 at pci0 dev 7 function 2: vendor 0x8086 product 0x7112 (rev. 0x01)
uhci0: interrupting at irq 10
usb0 at uhci0: USB revision 1.0
usbd_get_desc return status = 0
usbd_get_desc return status = 0
usbd_get_desc return status = 0
uhub0 at usb0
uhub0: vendor 0x8086 UHCI root hub, class 9/0, rev 1.00/1.00, addr 1
uhub0: 2 ports with 2 removable, self powered
vendor 0x8086 product 0x7113 (miscellaneous bridge, revision 0x03) at pci0 dev 
7 function 3 not configured
cbb0 at pci0 dev 10 function 0: vendor 0x104c product 0xac51 (rev. 0x00)
cbb1 at pci0 dev 10 function 1: vendor 0x104c product 0xac51 (rev. 0x00)
ex0 at pci0 dev 11 function 0: 3Com 3c556 MiniPCI 10/100 Ethernet (rev. 0x10)
ex0: interrupting at irq 10
ex0: MAC address 00:00:86:44:54:60
tqphy0 at ex0 phy 0: 78Q2120 10/100 media interface, rev. 11
tqphy0: 10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, auto
vendor 0x10b7 product 0x1007 (miscellaneous communications, revision 0x10) at 
pci0 dev 11 function 1 not configured
esa0 at pci0 dev 13 function 0: vendor 0x125d product 0x1998 (rev. 0x00)
esa0: interrupting at irq 5
esa0: SigmaTel STAC9721/23 codec; 18 bit DAC, 18 bit ADC, SigmaTel 3D
audio0 at esa0: full duplex, mmap, independent
isa0 at pcib0
com0 at isa0 port 0x3f8-0x3ff irq 4: ns16550a, working fifo
com1 at isa0 port 0x2f8-0x2ff irq 3: ns16550a, working fifo
pckbc0 at isa0 port 0x60-0x64
pckbd0 at pckbc0 (kbd slot)
pckbc0: using irq 1 for kbd slot
wskbd0 at pckbd0: console keyboard, using wsdisplay0
pms0 at pckbc0 (aux slot)
pckbc0: using irq 12 for aux slot
wsmouse0 at pms0 mux 0
lpt0 at isa0 port 0x378-0x37b irq 7
pcppi0 at isa0 port 0x61
sysbeep0 at pcppi0
isapnp0 at isa0 port 0x279: ISA Plug 'n Play device support
npx0 at isa0 port 0xf0-0xff: using exception 16
fdc0 at isa0 port 0x3f0-0x3f7 irq 6 drq 2
isapnp0: no ISA Plug 'n Play devices found
cbb0: interrupting at irq 10
cardslot0 at cbb0 slot 0 flags 0
cardbus0 at cardslot0: bus 2 device 0
pcmcia0 at cardslot0
cbb1: interrupting at irq 10
cardslot1 at cbb1 slot 1 flags 0
cardbus1 at cardslot1: bus 3 device 0
pcmcia1 at cardslot1
apm0 at mainbus0: Power Management spec V1.2
wi0 at pcmcia0 function 0: Lucent Technologies, WaveLAN/IEEE, Version 01.01
wi0: 802.11 address 00:02:2d:1f:3f:e8
wi0: using Lucent Technologies, WaveLAN/IEEE
wi0: Lucent Firmware: Station (8.10.1)
wi0: supported rates: 1Mbps 2Mbps 5.5Mbps 11Mbps
boot device: wd0
root on wd0a dumps on wd0b
root file system type: ffs