Subject: USB control endpoint stalled
To: None <tech-kern@netbsd.org>
From: Edgar =?iso-8859-1?B?RnXf?= <efnbl06@bn2.maus.net>
List: tech-kern
Date: 03/14/2007 18:42:38
Any USB stack experts around here?

The following problem arises while trying to talk to a Masterguard UPS.
The problem, once it occurs, seems to persists until we unplug (and replug)
the USB cable.
Possibly, its not primarily a fault of NetBSD's USB stack, but some sort
of misbehaviour of the client that the stack doesn't cope well with.

From reading the sources, what happens is that the control endpoint stalls
(whatever "stalls" exactly means). In ohci_softintr, after the "cc ="
line, the else clause seems to be executed. I don't undestand enough of
USB to see what's going on there.

However, I've got a bunch of debug output (I include the bits after the
STALL message in case it matters regarding recovery from this condition):

ugenioctl: cmd=c020556f
usbd_alloc_xfer() = 0xffff80000a05fd00
usbd_transfer: xfer=0xffff80000a05fd00, flags=6, pipe=0xffff800009111300, running=0
usbd_dump_queue: pipe=0xffff800009111300
usb_allocmem: use frag=0xffff80004ccc5ec0 size=3
usb_insert_transfer: pipe=0xffff800009111300 running=0 timeout=1500
ohci_device_control type=0x42, request=0x0d, wValue=0x0000, wIndex=0x0000 len=3, addr=2, endpt=0
ohci_alloc_std_chain: start len=3
ohci_alloc_std_chain: dataphys=0x07b9dec0 dataphysend=0x07b9d000 len=3 curlen=3
ohci_alloc_std_chain: cbp=0x07b9dec0 be=0x07b9dec2
ohci_device_request:
ED(0xffff80004cd087a0) at 0x07bdf7a0: addr=2 endpt=0 maxp=8 flags=82002<LOWSPEED>
tailp=0x082b45d0 headflags=82b45d0 headp=0x082b45d0 nexted=0x00000000
TD(0xffff80004dc4d5d0) at 082b45d0: f2e00000<SETTOGGLE> delay=7 ec=0 cc=15
cbp=0x07b9df40 nexttd=0x082b46c0 be=0x07b9df47
TD(0xffff80004dc4d6c0) at 082b46c0: f3ec0000<R,OUT,TOG1,SETTOGGLE> delay=7 ec=0 cc=15
cbp=0x07b9dec0 nexttd=0x082b4710 be=0x07b9dec2
TD(0xffff80004dc4d710) at 082b4710: f3300000<IN,TOG1,SETTOGGLE> delay=1 ec=0 cc=15
cbp=0x00000000 nexttd=0x082b4760 be=0x00000000
TD(0xffff80004dc4d760) at 082b4760: 0 delay=0 ec=0 cc=0
cbp=0x00000000 nexttd=0x00000000 be=0x00000000
ohci_intr1: enter
ohci_intr: sc=0xffff800009068000 intrs=0x26(0x2) eintrs=0x2
usb_schedsoftintr: polling=0
ohci1: blocking intrs 0x2
ohci_intr1: enter
ohci_softintr: enter
add TD 0xffff80004dc4d6c0
add TD 0xffff80004dc4d5d0
ohci_softintr: sdone=0xffff80004dc4d5d0 sidone=0x0
ohci_process_done: TD done:
TD(0xffff80004dc4d5d0) at 082b45d0: 3e00000<TOG1,SETTOGGLE> delay=7 ec=0 cc=0
cbp=0x00000000 nexttd=0x00000000 be=0x07b9df47
TD(0xffff80004dc4d6c0) at 082b46c0: 43ec0000<R,OUT,TOG1,SETTOGGLE> delay=7 ec=0 cc=4
cbp=0x07b9dec0 nexttd=0x082b45d0 be=0x07b9dec2
TD(0xffff80004dc4d710) at 082b4710: f3300000<IN,TOG1,SETTOGGLE> delay=1 ec=0 cc=15
cbp=0x00000000 nexttd=0x082b4760 be=0x00000000
TD(0xffff80004dc4d760) at 082b4760: 0 delay=0 ec=0 cc=0
cbp=0x00000000 nexttd=0x00000000 be=0x00000000
ohci_process_done: std=0xffff80004dc4d5d0 xfer=0xffff80000a05fd00 hcpriv=0xffff80004dc4d5d0
ohci_process_done: len=0, flags=0x0
ohci_process_done: std=0xffff80004dc4d6c0 xfer=0xffff80000a05fd00 hcpriv=0xffff80004dc4d5d0
ohci_process_done: len=0, flags=0x2
ohci_process_done: error cc=4 (STALL)
usb_transfer_complete: pipe=0xffff800009111300 xfer=0xffff80000a05fd00 status=17 actlen=0
usb_freemem: frag=0xffff80004ccc5ec0
usb_transfer_complete: repeat=0 new head=0x0
ohci_device_ctrl_done: xfer=0xffff80000a05fd00
usbd_start_next: pipe=0xffff800009111300, xfer=0x0
ohci_softintr: ITD done:
ohci_softintr: done:
usbd_transfer: xfer=0xffff80000a05fd00, flags=2, pipe=0xffff800009111300, running=0
usbd_dump_queue: pipe=0xffff800009111300
usb_allocmem: use frag=0xffff80004ccc5ec0 size=2
usb_insert_transfer: pipe=0xffff800009111300 running=0 timeout=5000
ohci_device_control type=0x82, request=0x00, wValue=0x0000, wIndex=0x0000 len=2, addr=2, endpt=0
ohci_alloc_std_chain: start len=2
ohci_alloc_std_chain: dataphys=0x07b9dec0 dataphysend=0x07b9d000 len=2 curlen=2
ohci_alloc_std_chain: cbp=0x07b9dec0 be=0x07b9dec1
ohci_device_request:
ED(0xffff80004cd087a0) at 0x07bdf7a0: addr=2 endpt=0 maxp=8 flags=82002<LOWSPEED>
tailp=0x082b4760 headflags=82b4760 headp=0x082b4760 nexted=0x00000000
TD(0xffff80004dc4d760) at 082b4760: f2e00000<SETTOGGLE> delay=7 ec=0 cc=15
cbp=0x07b9df40 nexttd=0x082b4710 be=0x07b9df47
TD(0xffff80004dc4d710) at 082b4710: f3f00000<IN,TOG1,SETTOGGLE> delay=7 ec=0 cc=15
cbp=0x07b9dec0 nexttd=0x082b45d0 be=0x07b9dec1
TD(0xffff80004dc4d5d0) at 082b45d0: f3280000<OUT,TOG1,SETTOGGLE> delay=1 ec=0 cc=15
cbp=0x00000000 nexttd=0x082b46c0 be=0x00000000
TD(0xffff80004dc4d6c0) at 082b46c0: 0 delay=0 ec=0 cc=0
cbp=0x00000000 nexttd=0x00000000 be=0x00000000
ohci_intr1: enter
ohci_intr: sc=0xffff800009068000 intrs=0x6(0x2) eintrs=0x2
usb_schedsoftintr: polling=0
ohci1: blocking intrs 0x2
ohci_intr1: enter
ohci_softintr: enter
add TD 0xffff80004dc4d5d0
add TD 0xffff80004dc4d710
add TD 0xffff80004dc4d760
ohci_softintr: sdone=0xffff80004dc4d760 sidone=0x0
ohci_process_done: TD done:
TD(0xffff80004dc4d760) at 082b4760: 3e00000<TOG1,SETTOGGLE> delay=7 ec=0 cc=0
cbp=0x00000000 nexttd=0x00000000 be=0x07b9df47
TD(0xffff80004dc4d710) at 082b4710: 2f00000<IN,SETTOGGLE> delay=7 ec=0 cc=0
cbp=0x00000000 nexttd=0x082b4760 be=0x07b9dec1
TD(0xffff80004dc4d5d0) at 082b45d0: 2280000<OUT,SETTOGGLE> delay=1 ec=0 cc=0
cbp=0x00000000 nexttd=0x082b4710 be=0x00000000
TD(0xffff80004dc4d6c0) at 082b46c0: 0 delay=0 ec=0 cc=0
cbp=0x00000000 nexttd=0x00000000 be=0x00000000
ohci_process_done: std=0xffff80004dc4d760 xfer=0xffff80000a05fd00 hcpriv=0xffff80004dc4d760
ohci_process_done: len=0, flags=0x0
ohci_process_done: std=0xffff80004dc4d710 xfer=0xffff80000a05fd00 hcpriv=0xffff80004dc4d760
ohci_process_done: len=2, flags=0x2
ohci_process_done: std=0xffff80004dc4d5d0 xfer=0xffff80000a05fd00 hcpriv=0xffff80004dc4d760
ohci_process_done: len=0, flags=0x1
usb_transfer_complete: pipe=0xffff800009111300 xfer=0xffff80000a05fd00 status=0 actlen=2
usb_freemem: frag=0xffff80004ccc5ec0
usb_transfer_complete: repeat=0 new head=0x0
ohci_device_ctrl_done: xfer=0xffff80000a05fd00
usbd_start_next: pipe=0xffff800009111300, xfer=0x0
ohci_softintr: ITD done:
ohci_softintr: done:
usbd_do_request: status = 0x0000
usbd_free_xfer: 0xffff80000a05fd00
ugenclose: flag=2, mode=8192, unit=0, endpt=0
ugenclose: close control
ugenclose: flag=1, mode=8192, unit=0, endpt=1
ugenclose: endpt=1 dir=1 sce=0xffff8000091164b8
usbd_ar_pipe: pipe=0xffff80000a05fe00
usbd_dump_queue: pipe=0xffff80000a05fe00
xfer=0xffff80000a05f100
usbd_ar_pipe: pipe=0xffff80000a05fe00 xfer=0xffff80000a05f100 (methods=0xffffffff805e6340)
ohci_device_intr_abort: remove
ohci_abort_xfer: xfer=0xffff80000a05f100 pipe=0xffff80000a05fe00 sed=0xffff80004cd08740
ohci_abort_xfer: stop ed=0xffff80004cd08740
usb_schedsoftintr: polling=0
ohci_softintr: enter
ohci_softintr: sdone=0x0 sidone=0x0
ohci_process_done: TD done:
ohci_softintr: ITD done:
ohci_softintr: done:
ohci_abort_xfer: sed=
ED(0xffff80004cd08740) at 0x07bdf740: addr=2 endpt=1 maxp=8 flags=86082<LOWSPEED,SKIP>
tailp=0x082b47b0 headflags=82b4670 headp=0x082b4670 nexted=0x07bdff60
TD(0xffff80004dc4d670) at 082b4670: 140000<R,IN> delay=0 ec=0 cc=0
cbp=0x07b9de80 nexttd=0x082b47b0 be=0x07b9de87
TD(0xffff80004dc4d7b0) at 082b47b0: 0 delay=0 ec=0 cc=0
cbp=0x00000000 nexttd=0x00000000 be=0x00000000
ohci_abort_xfer: set hd=0x082b47b0, tl=0x082b47b0
usb_transfer_complete: pipe=0xffff80000a05fe00 xfer=0xffff80000a05f100 status=6 actlen=0
usb_freemem: frag=0xffff80004ccc5e80
usb_transfer_complete: repeat=0 new head=0x0
ohci_device_intr_done: xfer=0xffff80000a05f100, actlen=0
ohci_device_intr_close: pipe=0xffff80000a05fe00 nslots=8 pos=3
usb_event_thread: woke up
usb_discover
usb_event_thread: woke up
usb_discover
ugenopen: flag=3, mode=8192, unit=0 endpt=0
ugenioctl: cmd=80045502