Problem with DVD writer and ehci on 4.10-STABLE

[James Collier]

I'm trying to get a USB2 DVD writer working with growisofs under 
4.10-STABLE (updated yesterday 6-Sep-04), but am having problems - the 
burn (on a DVD+R) always fails with an I/O Error anywhere between 10M 
and 1.5Gbytes.

I can read from the unit, and short burns seem OK.  There seems to be 
some correlation with system load, but my testing of this was 
inconclusive - long burns fail even when the system is quiescent.

I've now got to the point where I'm well out of my depth, and I was 
wondering whether anyone can tell me whether I'm wasting my time on 
this.  I'm aware of some problems with ehci, but not sure if this is a 
symptom ...

The units in question are:
NEC uPD 720100 USB 2.0     Host controller
Genesys GL811              USB2/ATA Bridge
NEC 1300A Rev 1.08         DVD writer
I had to modify my umass.c to work with the GL811 bridge (note that the 
vendor/product ID matches USB_PRODUCT_GENESYS_GL641USB2IDE_2):
--------------------------------------------------------------
*** .orig/umass.c       Mon Sep  6 19:03:50 2004
--- ./umass.c   Mon Sep  6 21:25:32 2004
***************
*** 703,706 ****
--- 703,707 ----
    UGETW(dd->idProduct) == USB_PRODUCT_GENESYS_GL641USB2IDE_2 ||
    UGETW(dd->idProduct) == USB_PRODUCT_GENESYS_GL641USB)) {
+        sc->proto =  UMASS_PROTO_SCSI | UMASS_PROTO_BBB;
         sc->quirks |= FORCE_SHORT_INQUIRY | NO_START_STOP | 
IGNORE_RESIDUE;
    }
--------------------------------------------------------------
[IMHO it would be nice if this stuff could be configurable in the 
pattern of /etc/pccard.conf but ...]

I enabled CAM and USB debugging, and caught the point of failure (two 
traces with varying levels of debugging attached).

Having stared dumbly at the trace, code and the EHCI spec for long 
enough, it appears that the unit is returning a transaction error 
(XACTERR - possibly a timeout) implying that the transaction should be 
retried (EHCI spec 4.12.1.2), but it seems that this is not happening.

If this problem is considered interesting enough I can supply more 
background detail (config file and/or boot log - but the boot log is a 
hideous length with full debugging enabled.)

Any advice - no matter how pointed - will be appeciated.
Thanks & regards
    James Collier.
--------------------------------------------------------------
Trace #1 - hw.usb.ehci.debug=1
--------------------------------------------------------------
Sep  7 13:54:10 tigger /kernel: (pass0:umass-sim0:0:1:0): WRITE(10). 
CDB: 2a 0 0 0 c7 90 0 0 10 0
Sep  7 13:54:10 tigger /kernel: ehci_alloc_sqtd_chain: start len=32768
Sep  7 13:54:10 tigger /kernel: (pass0:umass-sim0:0:1:0): xpt_done
Sep  7 13:54:10 tigger /kernel: (pass0:umass-sim0:0:1:0): camisr
Sep  7 13:54:10 tigger /kernel: (pass0:umass-sim0:0:1:0): entering cdgetccb
Sep  7 13:54:10 tigger /kernel: (pass0:umass-sim0:0:1:0): xpt_schedule
Sep  7 13:54:10 tigger /kernel: (pass0:umass-sim0:0:1:0): xpt_setup_ccb
Sep  7 13:54:10 tigger /kernel: (pass0:umass-sim0:0:1:0): xpt_action
Sep  7 13:54:10 tigger /kernel: (pass0:umass-sim0:0:1:0): WRITE(10). 
CDB: 2a 0 0 0 c7 a0 0 0 10 0
Sep  7 13:54:10 tigger /kernel: ehci_alloc_sqtd_chain: start len=32768
Sep  7 13:54:10 tigger /kernel: (pass0:umass-sim0:0:1:0): xpt_done
Sep  7 13:54:10 tigger /kernel: (pass0:umass-sim0:0:1:0): camisr
Sep  7 13:54:10 tigger /kernel: (pass0:umass-sim0:0:1:0): entering cdgetccb
Sep  7 13:54:10 tigger /kernel: (pass0:umass-sim0:0:1:0): xpt_schedule
Sep  7 13:54:10 tigger /kernel: (pass0:umass-sim0:0:1:0): xpt_setup_ccb
Sep  7 13:54:10 tigger /kernel: (pass0:umass-sim0:0:1:0): xpt_action
Sep  7 13:54:10 tigger /kernel: (pass0:umass-sim0:0:1:0): WRITE(10). 
CDB: 2a 0 0 0 c7 b0 0 0 10 0
Sep  7 13:54:10 tigger /kernel: ehci_alloc_sqtd_chain: start len=32768
Sep  7 13:54:10 tigger /kernel: ehci_idone: error, addr=2, endpt=0x02, 
status 0x8<XACT>
Sep  7 13:54:10 tigger /kernel: ehci_device_clear_toggle: 
epipe=0xc15fec00 status=0x8d00
Sep  7 13:54:10 tigger /kernel: usbd_dump_pipe: pipe=0xc15fec00
Sep  7 13:54:10 tigger /kernel: usbd_dump_iface: iface=0xc15f8e60
Sep  7 13:54:10 tigger /kernel: device=0xc15fee00 idesc=0xc15f8e89 
index=0 altindex=0 priv=0
Sep  7 13:54:10 tigger /kernel: usbd_dump_device: dev=0xc15fee00
Sep  7 13:54:10 tigger /kernel: bus=0xc15ee400 default_pipe=0xc15fed80
Sep  7 13:54:10 tigger /kernel: address=2 config=1 depth=1 speed=3 
self_powered=1 power=4 langid=1033
Sep  7 13:54:10 tigger /kernel: usbd_dump_endpoint: endp=0xc15d87f0
Sep  7 13:54:10 tigger /kernel: edesc=0xc15f8e92 refcnt=1
Sep  7 13:54:10 tigger /kernel: bEndpointAddress=0x81
Sep  7 13:54:10 tigger /kernel: (usbd_dump_pipe:)
Sep  7 13:54:10 tigger /kernel: refcnt=1 running=0 aborting=0
Sep  7 13:54:10 tigger /kernel: intrxfer=0, repeat=0, interval=-1
Sep  7 13:54:10 tigger /kernel: ehci_device_clear_toggle: 
epipe=0xc15fec80 status=0x9c08
Sep  7 13:54:10 tigger /kernel: usbd_dump_pipe: pipe=0xc15fec80
Sep  7 13:54:10 tigger /kernel: usbd_dump_iface: iface=0xc15f8e60
Sep  7 13:54:10 tigger /kernel: device=0xc15fee00 idesc=0xc15f8e89 
index=0 altindex=0 priv=0
Sep  7 13:54:10 tigger /kernel: usbd_dump_device: dev=0xc15fee00
Sep  7 13:54:10 tigger /kernel: bus=0xc15ee400 default_pipe=0xc15fed80
Sep  7 13:54:10 tigger /kernel: address=2 config=1 depth=1 speed=3 
self_powered=1 power=4 langid=1033
Sep  7 13:54:10 tigger /kernel: usbd_dump_endpoint: endp=0xc15d87f8
Sep  7 13:54:10 tigger /kernel: edesc=0xc15f8e99 refcnt=1
Sep  7 13:54:10 tigger /kernel: bEndpointAddress=0x02
Sep  7 13:54:10 tigger /kernel: (usbd_dump_pipe:)
Sep  7 13:54:10 tigger /kernel: refcnt=1 running=0 aborting=0
Sep  7 13:54:10 tigger /kernel: intrxfer=0, repeat=0, interval=-1
Sep  7 13:54:10 tigger /kernel: (pass0:umass-sim0:0:1:0): xpt_done
Sep  7 13:54:10 tigger /kernel: (pass0:umass-sim0:0:1:0): camisr
Sep  7 13:54:10 tigger /kernel: (pass0:umass-sim0:0:1:0): entering cdgetccb
Sep  7 13:54:10 tigger /kernel: (pass0:umass-sim0:0:1:0): xpt_schedule
Sep  7 13:54:10 tigger /kernel: (pass0:umass-sim0:0:1:0): xpt_setup_ccb
Sep  7 13:54:10 tigger /kernel: (pass0:umass-sim0:0:1:0): xpt_action
Sep  7 13:54:10 tigger /kernel: (pass0:umass-sim0:0:1:0): SYNCHRONIZE 
CACHE. CDB: 35 2 0 0 0 0 0 0 0 0
Sep  7 13:54:10 tigger /kernel: (pass0:umass-sim0:0:1:0): xpt_done
Sep  7 13:54:10 tigger /kernel: (pass0:umass-sim0:0:1:0): camisr
Sep  7 13:54:11 tigger /kernel: (pass0:umass-sim0:0:1:0): entering cdgetccb
Sep  7 13:54:11 tigger /kernel: (pass0:umass-sim0:0:1:0): xpt_schedule
Sep  7 13:54:11 tigger /kernel: (pass0:umass-sim0:0:1:0): xpt_setup_ccb
Sep  7 13:54:11 tigger /kernel: (pass0:umass-sim0:0:1:0): xpt_action
Sep  7 13:54:11 tigger /kernel: (pass0:umass-sim0:0:1:0): TEST UNIT 
READY. CDB: 0 0 0 0 0 0
Sep  7 13:54:12 tigger /kernel: (pass0:umass-sim0:0:1:0): xpt_done
Sep  7 13:54:12 tigger /kernel: (pass0:umass-sim0:0:1:0): camisr
Sep  7 13:54:12 tigger /kernel: (pass0:umass-sim0:0:1:0): entering cdgetccb
Sep  7 13:54:12 tigger /kernel: (pass0:umass-sim0:0:1:0): xpt_schedule
Sep  7 13:54:12 tigger /kernel: (pass0:umass-sim0:0:1:0): xpt_setup_ccb
Sep  7 13:54:12 tigger /kernel: (pass0:umass-sim0:0:1:0): xpt_action
Sep  7 13:54:12 tigger /kernel: (pass0:umass-sim0:0:1:0): SYNCHRONIZE 
CACHE. CDB: 35 0 0 0 0 0 0 0 0 0
--------------------------------------------------------------

Trace #2:
Drilling down on a subsequent run (hw.usb.ehci.debug=3), we see:
--------------------------------------------------------------
Sep  7 17:29:44 tigger /kernel: (pass0:umass-sim0:0:1:0): WRITE(10). 
CDB: 2a 0 0 0 da 50 0 0 10 0
Sep  7 17:29:44 tigger /kernel: ehci_device_bulk_transfer: 
xfer=0xc15f7100 len=31 flags=0
Sep  7 17:29:44 tigger /kernel: ehci_alloc_sqtd_chain: start len=31
Sep  7 17:29:44 tigger /kernel: ehci_check_intr: ex=0xc15f7100
Sep  7 17:29:44 tigger /kernel: ehci_idone: ex=0xc15f7100
Sep  7 17:29:44 tigger /kernel: ehci_idone: xfer=0xc15f7100, 
pipe=0xc15fec80 ready
Sep  7 17:29:44 tigger /kernel: ehci_idone: len=31, actlen=31, status=0x0
Sep  7 17:29:44 tigger /kernel: ehci_device_bulk_transfer: 
xfer=0xc1602f00 len=32768 flags=0
Sep  7 17:29:44 tigger /kernel: ehci_alloc_sqtd_chain: start len=32768
Sep  7 17:29:44 tigger /kernel: ehci_alloc_sqtd_chain: multiple QTDs, 
curlen=4096
Sep  7 17:29:44 tigger last message repeated 6 times
Sep  7 17:29:44 tigger /kernel: ehci_idone: ex=0xc15f7100 done
Sep  7 17:29:44 tigger /kernel: ehci_check_intr: ex=0xc1602f00
Sep  7 17:29:44 tigger /kernel: ehci_idone: ex=0xc1602f00
Sep  7 17:29:44 tigger /kernel: ehci_idone: xfer=0xc1602f00, 
pipe=0xc15fec80 ready
Sep  7 17:29:44 tigger /kernel: ehci_idone: len=32768, actlen=32768, 
status=0x8
Sep  7 17:29:44 tigger /kernel: ehci_idone: error, addr=2, endpt=0x02, 
status 0x8<XACT>
Sep  7 17:29:44 tigger /kernel: QH(0xc15fdea0) at 0x0f871ea0:
Sep  7 17:29:44 tigger /kernel: link=0x0f871f02<QH>
Sep  7 17:29:44 tigger /kernel: endp=0x82002202
Sep  7 17:29:44 tigger /kernel: addr=0x02 inact=0 endpt=2 eps=2 dtc=0 
hrecl=0
Sep  7 17:29:44 tigger /kernel: mpl=0x200 ctl=0 nrl=8
Sep  7 17:29:44 tigger /kernel: endphub=0x40000000
Sep  7 17:29:44 tigger /kernel: smask=0x00 cmask=0x00 huba=0x00 port=0 
mult=1
Sep  7 17:29:44 tigger /kernel: curqtd=0x0f834e40<>
Sep  7 17:29:44 tigger /kernel: Overlay qTD:
Sep  7 17:29:44 tigger /kernel: next=0x00000001<T> altnext=0x00000011<T>
Sep  7 17:29:44 tigger /kernel: status=0x80009c08: toggle=1 bytes=0x0 
ioc=1 c_page=0x1
Sep  7 17:29:44 tigger /kernel: cerr=3 pid=0 stat=0x8<XACTERR>
Sep  7 17:29:44 tigger /kernel: buffer[0]=0x00023000
Sep  7 17:29:44 tigger /kernel: buffer[1]=0x00000000
Sep  7 17:29:44 tigger /kernel: buffer[2]=0x00000000
Sep  7 17:29:44 tigger /kernel: buffer[3]=0x00000000
Sep  7 17:29:44 tigger /kernel: buffer[4]=0x00000000
Sep  7 17:29:44 tigger /kernel: QTD(0xc1600f00) at 0x0f834f00:
Sep  7 17:29:44 tigger /kernel: next=0x0f834c00<> altnext=0x0f834c00<>
Sep  7 17:29:44 tigger /kernel: status=0x80001c00: toggle=1 bytes=0x0 
ioc=0 c_page=0x1
Sep  7 17:29:44 tigger /kernel: cerr=3 pid=0 stat=0x0
Sep  7 17:29:44 tigger /kernel: buffer[0]=0x0001c000
Sep  7 17:29:44 tigger /kernel: buffer[1]=0x00000000
Sep  7 17:29:44 tigger /kernel: buffer[2]=0x00000000
Sep  7 17:29:44 tigger /kernel: buffer[3]=0x00000000
Sep  7 17:29:44 tigger /kernel: buffer[4]=0x00000000
......
Sep  7 17:29:44 tigger /kernel: QTD(0xc1600c00) at 0x0f834c00:
......
Sep  7 17:29:44 tigger /kernel: status=0x80001c00: toggle=1 bytes=0x0 
ioc=0 c_page=0x1
......
Sep  7 17:29:44 tigger /kernel: QTD(0xc1600c60) at 0x0f834c60:
......
Sep  7 17:29:44 tigger /kernel: status=0x80001c00: toggle=1 bytes=0x0 
ioc=0 c_page=0x1
......
Sep  7 17:29:44 tigger /kernel: QTD(0xc1600cc0) at 0x0f834cc0:
......
Sep  7 17:29:44 tigger /kernel: status=0x80001c00: toggle=1 bytes=0x0 
ioc=0 c_page=0x1
......
Sep  7 17:29:44 tigger /kernel: QTD(0xc1600d20) at 0x0f834d20:
......
Sep  7 17:29:44 tigger /kernel: status=0x80001c00: toggle=1 bytes=0x0 
ioc=0 c_page=0x1
......
Sep  7 17:29:44 tigger /kernel: QTD(0xc1600d80) at 0x0f834d80:
......
Sep  7 17:29:44 tigger /kernel: status=0x80001c00: toggle=1 bytes=0x0 
ioc=0 c_page=0x1
......
Sep  7 17:29:44 tigger /kernel: QTD(0xc1600de0) at 0x0f834de0:
......
Sep  7 17:29:44 tigger /kernel: status=0x80001c00: toggle=1 bytes=0x0 
ioc=0 c_page=0x1
......
Sep  7 17:29:44 tigger /kernel: QTD(0xc1600e40) at 0x0f834e40:
......
Sep  7 17:29:44 tigger /kernel: status=0x80009c08: toggle=1 bytes=0x0 
ioc=1 c_page=0x1
Sep  7 17:29:44 tigger /kernel: QTD(0xc1600e40) at 0x0f834e40:
Sep  7 17:29:44 tigger /kernel: next=0x00000001<T> altnext=0x00000001<T>
Sep  7 17:29:44 tigger /kernel: status=0x80009c08: toggle=1 bytes=0x0 
ioc=1 c_page=0x1
Sep  7 17:29:44 tigger /kernel: cerr=3 pid=0 stat=0x8<XACTERR>
Sep  7 17:29:44 tigger /kernel: buffer[0]=0x00023000
Sep  7 17:29:44 tigger /kernel: buffer[1]=0x00000000
Sep  7 17:29:44 tigger /kernel: buffer[2]=0x00000000
Sep  7 17:29:44 tigger /kernel: buffer[3]=0x00000000
Sep  7 17:29:44 tigger /kernel: buffer[4]=0x00000000
Sep  7 17:29:44 tigger /kernel: ehci_idone: ex=0xc1602f00 done
Sep  7 17:29:44 tigger /kernel: ehci_check_intr: ex=0xc1602a00
Sep  7 17:29:44 tigger /kernel: ehci_idone: ex=0xc1602a00
Sep  7 17:29:44 tigger /kernel: ehci_idone: xfer=0xc1602a00, 
pipe=0xc15fed80 ready
Sep  7 17:29:44 tigger /kernel: ehci_idone: len=0, actlen=0, status=0x0
Sep  7 17:29:44 tigger /kernel: ehci_device_clear_toggle: 
epipe=0xc15fec00 status=0x8d00
Sep  7 17:29:44 tigger /kernel: usbd_dump_pipe: pipe=0xc15fec00
Sep  7 17:29:44 tigger /kernel: usbd_dump_iface: iface=0xc15f8e60
Sep  7 17:29:44 tigger /kernel: device=0xc15fee00 idesc=0xc15f8e89 
index=0 altindex=0 priv=0
Sep  7 17:29:44 tigger /kernel: usbd_dump_device: dev=0xc15fee00
Sep  7 17:29:45 tigger /kernel: bus=0xc15ee400 default_pipe=0xc15fed80
Sep  7 17:29:45 tigger /kernel: address=2 config=1 depth=1 speed=3 
self_powered=1 power=4 langid=1033
Sep  7 17:29:45 tigger /kernel: usbd_dump_endpoint: endp=0xc15d87f0
Sep  7 17:29:45 tigger /kernel: edesc=0xc15f8e92 refcnt=1
Sep  7 17:29:45 tigger /kernel: bEndpointAddress=0x81
Sep  7 17:29:45 tigger /kernel: (usbd_dump_pipe:)
Sep  7 17:29:45 tigger /kernel: refcnt=1 running=0 aborting=0
Sep  7 17:29:45 tigger /kernel: intrxfer=0, repeat=0, interval=-1
Sep  7 17:29:45 tigger /kernel: ehci_idone: ex=0xc1602a00 done
Sep  7 17:29:45 tigger /kernel: ehci_check_intr: ex=0xc1602900
Sep  7 17:29:45 tigger /kernel: ehci_idone: ex=0xc1602900
Sep  7 17:29:45 tigger /kernel: ehci_idone: xfer=0xc1602900, 
pipe=0xc15fed80 ready
Sep  7 17:29:45 tigger /kernel: ehci_idone: len=0, actlen=0, status=0x0
Sep  7 17:29:45 tigger /kernel: ehci_device_clear_toggle: 
epipe=0xc15fec80 status=0x80009c08
Sep  7 17:29:45 tigger /kernel: usbd_dump_pipe: pipe=0xc15fec80
Sep  7 17:29:45 tigger /kernel: usbd_dump_iface: iface=0xc15f8e60
Sep  7 17:29:45 tigger /kernel: device=0xc15fee00 idesc=0xc15f8e89 
index=0 altindex=0 priv=0
Sep  7 17:29:45 tigger /kernel: usbd_dump_device: dev=0xc15fee00
Sep  7 17:29:45 tigger /kernel: bus=0xc15ee400 default_pipe=0xc15fed80
Sep  7 17:29:45 tigger /kernel: address=2 config=1 depth=1 speed=3 
self_powered=1 power=4 langid=1033
Sep  7 17:29:45 tigger /kernel: usbd_dump_endpoint: endp=0xc15d87f8
Sep  7 17:29:45 tigger /kernel: edesc=0xc15f8e99 refcnt=1
Sep  7 17:29:45 tigger /kernel: bEndpointAddress=0x02
Sep  7 17:29:45 tigger /kernel: (usbd_dump_pipe:)
Sep  7 17:29:45 tigger /kernel: refcnt=1 running=0 aborting=0
Sep  7 17:29:45 tigger /kernel: intrxfer=0, repeat=0, interval=-1
Sep  7 17:29:45 tigger /kernel: ehci_idone: ex=0xc1602900 done
Sep  7 17:29:45 tigger /kernel: ehci_check_intr: ex=0xc1602800
Sep  7 17:29:45 tigger /kernel: ehci_idone: ex=0xc1602800
Sep  7 17:29:45 tigger /kernel: ehci_idone: xfer=0xc1602800, 
pipe=0xc15fed80 ready
Sep  7 17:29:45 tigger /kernel: ehci_idone: len=0, actlen=0, status=0x0
Sep  7 17:29:45 tigger /kernel: (pass0:umass-sim0:0:1:0): xpt_done
Sep  7 17:29:45 tigger /kernel: ehci_idone: ex=0xc1602800 done
Sep  7 17:29:45 tigger /kernel: (pass0:umass-sim0:0:1:0): camisr

-----------------------------------------------------------------------------------
[End of traces]
_______________________________________________
[EMAIL PROTECTED] mailing list
http://lists.freebsd.org/mailman/listinfo/freebsd-hackers
To unsubscribe, send any mail to "[EMAIL PROTECTED]"