usb/91538: Unable to print to EPSON CX3500

[Peter Jeremy]

>Number:         91538
>Category:       usb
>Synopsis:       Unable to print to EPSON CX3500
>Confidential:   no
>Severity:       serious
>Priority:       medium
>Responsible:    freebsd-usb
>State:          open
>Quarter:        
>Keywords:       
>Date-Required:
>Class:          sw-bug
>Submitter-Id:   current-users
>Arrival-Date:   Mon Jan 09 00:50:03 GMT 2006
>Closed-Date:
>Last-Modified:
>Originator:     Peter Jeremy
>Release:        FreeBSD 7.0-CURRENT i386
>Organization:
n/a
>Environment:
System: FreeBSD server.vk2pj.dyndns.org 7.0-CURRENT FreeBSD 7.0-CURRENT #23: Mon Jan 9 08:37:53 EST 2006 root at server.vk2pj.dyndns.org:/var/obj/k7/usr/src/sys/server i386

7.0-CURRENT from about Jan 7 1200 UTC.
pips-scx3500_3600s-2.6.2

Relevant bits of dmesg are:
uhci0: <VIA 83C572 USB controller> port 0xe400-0xe41f irq 10 at device 17.2 on pci0
uhci0: [GIANT-LOCKED]
usb0: <VIA 83C572 USB controller> on uhci0
usb0: USB revision 1.0
usbd_get_string: getting lang failed, using 0
uhub0: VIA UHCI root hub, class 9/0, rev 1.00/1.00, addr 1
uhub0: 2 ports with 2 removable, self powered
uhci1: <VIA 83C572 USB controller> port 0xe000-0xe01f irq 10 at device 17.3 on pci0
uhci1: [GIANT-LOCKED]
usb1: <VIA 83C572 USB controller> on uhci1
usb1: USB revision 1.0
usbd_get_string: getting lang failed, using 0
uhub1: VIA UHCI root hub, class 9/0, rev 1.00/1.00, addr 1
uhub1: 2 ports with 2 removable, self powered
uhci2: <VIA 83C572 USB controller> port 0xdc00-0xdc1f irq 5 at device 20.0 on pci0
uhci2: [GIANT-LOCKED]
usb2: <VIA 83C572 USB controller> on uhci2
usb2: USB revision 1.0
usbd_get_string: getting lang failed, using 0
uhub2: VIA UHCI root hub, class 9/0, rev 1.00/1.00, addr 1
uhub2: 2 ports with 2 removable, self powered
uhci3: <VIA 83C572 USB controller> port 0xd800-0xd81f irq 5 at device 20.1 on pci0
uhci3: [GIANT-LOCKED]
usb3: <VIA 83C572 USB controller> on uhci3
usb3: USB revision 1.0
usbd_get_string: getting lang failed, using 0
uhub3: VIA UHCI root hub, class 9/0, rev 1.00/1.00, addr 1
uhub3: 2 ports with 2 removable, self powered
ehci0: <VIA VT6202 USB 2.0 controller> mem 0xdffffb00-0xdffffbff irq 11 at device 20.2 on pci0
ehci0: [GIANT-LOCKED]
usb4: EHCI version 0.95
usb4: companion controllers, 2 ports each: usb2 usb3
usb4: <VIA VT6202 USB 2.0 controller> on ehci0
usb4: USB revision 2.0
uhub4: VIA EHCI root hub, class 9/0, rev 2.00/1.00, addr 1
uhub4: 4 ports with 4 removable, self powered

>Description:

Attempting to access an EPSON Stylus CX3500 printer fails and locks
up the uhub until the system is rebooted.  I believe this is a problem
with the USB subsystem rather than the port because of the lockup.

I have posted this problem in freebsd-usb and tried contacting the
people mentioned in the PIPS port with no response.

>How-To-Repeat:

Enable USB_DEBUG and set the sysctl variables as follows:
hw.usb.debug: 1
hw.usb.ehci.debug: 1
hw.usb.uhci.debug: 1
hw.usb.ulpt.debug: 3

Plug in the printer.  The following shows the behaviour on a USB1 port but
the behaviour is the same on a USB2 port.  The following console output
is generated:
 usbd_new_device bus=0xc3447000 port=1 depth=1 speed=2
 usbd_new_device: adding unit addr=2, rev=110, class=0, subclass=0, protocol=0, maxpacket=8, len=18, speed=2
 usbd_new_device: new dev (addr 2), dev=0xc560b280, parent=0xc3439880
 usbd_probe_and_attach: trying device specific drivers
 usbd_probe_and_attach: no device specific driver found
 usbd_probe_and_attach: looping over 1 configurations
 usbd_set_config_index: status=0x0001, error=NORMAL_COMPLETION
 usbd_set_config_index: (addr 1) cno=2 attr=0xc0, selfpowered=1, power=2
 usbd_set_config_index: set config 1
 ulpt0: EPSON USB MFP, rev 1.10/1.00, addr 2, iclass 255/255
 ulpt0: using bi-directional mode

Run /usr/local/libexec/pips/printer/ekpd as root.
Start /usr/local/bin/ekpstm from an xterm.  This generates the following
console output:
 ulptopen: flags=0x40
 ulpt_open: open input pipe
 ulptopen: done, error=0
 ulptread
 ulptread: transfer 1024 bytes
 ulptread
 ulptread: transfer 1024 bytes
 ulptwrite
 ulpt_status: status=0x18 err=0
 ulptwrite: transfer 27 bytes
 ulptread
 ulptread: transfer 8 bytes
 ulptwrite
 ulpt_status: status=0x18 err=0
 ulptwrite: transfer 8 bytes
 ulptread
 ulptread: transfer 9 bytes
 ulptwrite
 ulpt_status: status=0x18 err=0
 ulptwrite: transfer 17 bytes
 ulptread
 ulptread: transfer 16 bytes
 ulptwrite
 ulpt_status: status=0x18 err=0
 ulptwrite: transfer 13 bytes
 ulptread
 ulptread: transfer 12 bytes
 ulptwrite
 ulpt_status: status=0x18 err=0
 ulptwrite: transfer 11 bytes
 ulptwrite
 ulpt_status: status=0x18 err=0
 ulptwrite: transfer 11 bytes
 ulptread
 ulptread: transfer 10 bytes
 ulptread
 ulptread: transfer 6 bytes
 uhci_idone: error, addr=2, endpt=0x83, status 0x500000<BABBLE,STALLED>
 usbd_bulk_transfer: error=13
 uhci_timeout: uxfer=0xc5b56300
 uhci_timeout_task: xfer=0xc5b56300
 uhci_check_intr: aborted xfer=0xc5b56300
 ulptread: error=13
 ulptread
 ulptread: transfer 6 bytes
 usbd_bulk_transfer: tsleep=-1
 uhci_device_bulk_abort:
 uhci_check_intr: aborted xfer=0xc5bc2e00
 ulptread: error=18
 ulptread
 ulptread: transfer 6 bytes
 usbd_bulk_transfer: tsleep=-1
 uhci_device_bulk_abort:
 uhci_check_intr: aborted xfer=0xc5bc2e00
 ulptread: error=18

Note that error 13 is USBD_IOERROR (reported because BABBLE is set),
error 18 is USBD_INTERRUPTED.

At this point, the last 6 lines will repeat indefinitely until ekpd is killed.
Killing ekpd will give:
 ulptclose: closed

Disconnecting the printer gives:
 ulpt0: at uhub1 port 1 (addr 2) disconnected
 ulpt_detach: sc=0xc560ed00
 uhci_timeout: uxfer=0xc5bc2e00
 uhci_timeout_task: xfer=0xc5bc2e00
 uhci_check_intr: aborted xfer=0xc5bc2e00
 uhci_timeout: uxfer=0xc5bc2e00
 uhci_timeout_task: xfer=0xc5bc2e00
 uhci_check_intr: aborted xfer=0xc5bc2e00
 ulpt0: detached

Re-connecting the printer, or any other USB device, to the same hub then gives:
 usbd_new_device bus=0xc3447000 port=1 depth=1 speed=2
 uhci_timeout: uxfer=0xc5bc2e00
 uhci_timeout_task: xfer=0xc5bc2e00
 uhci_check_intr: aborted xfer=0xc5bc2e00
 uhci_timeout: uxfer=0xc5bc2e00
 uhci_timeout_task: xfer=0xc5bc2e00
 uhci_check_intr: aborted xfer=0xc5bc2e00
 uhci_timeout: uxfer=0xc5bc2e00
 uhci_timeout_task: xfer=0xc5bc2e00
 uhci_check_intr: aborted xfer=0xc5bc2e00
 uhci_timeout: uxfer=0xc5bc2e00
 uhci_timeout_task: xfer=0xc5bc2e00
 uhci_check_intr: aborted xfer=0xc5bc2e00
 usb_new_device: set address 2 failed - trying a port reset
 [above 13 lines repeat twice]
 uhci_timeout: uxfer=0xc5bc2e00
 uhci_timeout_task: xfer=0xc5bc2e00
 uhci_check_intr: aborted xfer=0xc5bc2e00
 uhci_timeout: uxfer=0xc5bc2e00
 uhci_timeout_task: xfer=0xc5bc2e00
 uhci_check_intr: aborted xfer=0xc5bc2e00
 uhci_timeout: uxfer=0xc5bc2e00
 uhci_timeout_task: xfer=0xc5bc2e00
 uhci_check_intr: aborted xfer=0xc5bc2e00
 usb_new_device: set address 2 failed
 usbd_remove_device: 0xc5954d80
 uhub_explore: usb_new_device failed, error=SET_ADDR_FAILED
 uhub1: device problem (SET_ADDR_FAILED), disabling port 1

>Fix:

	unknown.
>Release-Note:
>Audit-Trail:
>Unformatted: