Re: PROBLEM: USB ACM device does not work

From: Arseniy Lartsev
Date: Tue Jun 30 2009 - 16:10:15 EST

On Tuesday 30 June 2009 11:22:04 Oliver Neukum wrote:
> Yet, your device shows bulk endpoints. Please enable DEBUG in cdc-acm.c
> and recompile with CONFIG_USB_DEBUG.

I've recompiled four modules usbcore, ehci_hcd, ohci_hcd and cdc-acm with -DDEBUG.
Here is kernel log:

======================== Device plugged in ========================
Jun 30 23:58:34 noteb00k kernel: usb usb1: usb resume
Jun 30 23:58:34 noteb00k kernel: ehci_hcd 0000:00:03.3: resume root hub
Jun 30 23:58:35 noteb00k kernel: ehci_hcd 0000:00:03.3: port 5 low speed --> companion
Jun 30 23:58:35 noteb00k kernel: ehci_hcd 0000:00:03.3: GetStatus port 5 status 003002 POWER OWNER sig=se0 CSC
Jun 30 23:58:35 noteb00k kernel: hub 1-0:1.0: hub_resume
Jun 30 23:58:35 noteb00k kernel: usb usb2: usb resume
Jun 30 23:58:35 noteb00k kernel: hub 1-0:1.0: state 7 ports 6 chg 0000 evt 0000
Jun 30 23:58:35 noteb00k kernel: ohci_hcd 0000:00:03.0: wakeup root hub
Jun 30 23:58:35 noteb00k kernel: hub 2-0:1.0: hub_resume
Jun 30 23:58:35 noteb00k kernel: ohci_hcd 0000:00:03.0: GetStatus roothub.portstatus [2] = 0x00010301 CSC LSDA PPS
CCS
Jun 30 23:58:35 noteb00k kernel: hub 2-0:1.0: port 3: status 0301 change 0001
Jun 30 23:58:35 noteb00k kernel: hub 2-0:1.0: state 7 ports 3 chg 0008 evt 0000
Jun 30 23:58:35 noteb00k kernel: hub 2-0:1.0: port 3, status 0301, change 0000, 1.5 Mb/s
Jun 30 23:58:35 noteb00k kernel: ohci_hcd 0000:00:03.0: GetStatus roothub.portstatus [2] = 0x00100303 PRSC LSDA PPS
PES CCS
Jun 30 23:58:35 noteb00k kernel: usb 2-3: new low speed USB device using ohci_hcd and address 5
Jun 30 23:58:35 noteb00k kernel: ohci_hcd 0000:00:03.0: GetStatus roothub.portstatus [2] = 0x00100303 PRSC LSDA PPS
PES CCS
Jun 30 23:58:35 noteb00k kernel: usb 2-3: skipped 4 descriptors after interface
Jun 30 23:58:35 noteb00k kernel: usb 2-3: config 1 interface 1 altsetting 0 endpoint 0x1 is Bulk; changing to
Interrupt
Jun 30 23:58:35 noteb00k kernel: usb 2-3: config 1 interface 1 altsetting 0 endpoint 0x81 is Bulk; changing to
Interrupt
Jun 30 23:58:35 noteb00k kernel: usb 2-3: default language 0x0409
Jun 30 23:58:35 noteb00k kernel: usb 2-3: udev 5, busnum 2, minor = 132
Jun 30 23:58:35 noteb00k kernel: usb 2-3: New USB device found, idVendor=16c0, idProduct=05e1
Jun 30 23:58:35 noteb00k kernel: usb 2-3: New USB device strings: Mfr=1, Product=2, SerialNumber=0
Jun 30 23:58:35 noteb00k kernel: usb 2-3: Product: AVR910 USB Programmer
Jun 30 23:58:35 noteb00k kernel: usb 2-3: Manufacturer: PROTTOSS
Jun 30 23:58:35 noteb00k kernel: usb 2-3: uevent
Jun 30 23:58:35 noteb00k kernel: usb 2-3: usb_probe_device
Jun 30 23:58:35 noteb00k kernel: usb 2-3: configuration #1 chosen from 1 choice
Jun 30 23:58:35 noteb00k kernel: usb 2-3: adding 2-3:1.0 (config #1, interface 0)
Jun 30 23:58:35 noteb00k kernel: usb 2-3:1.0: uevent
Jun 30 23:58:35 noteb00k kernel: cdc_acm 2-3:1.0: usb_probe_interface
Jun 30 23:58:35 noteb00k kernel: cdc_acm 2-3:1.0: usb_probe_interface - got id
Jun 30 23:58:35 noteb00k kernel: cdc_acm 2-3:1.0: The data interface has switched endpoints
Jun 30 23:58:35 noteb00k kernel: /w/work/lesh/research/driver/cdc-acm.c: interfaces are valid
Jun 30 23:58:35 noteb00k kernel: cdc_acm 2-3:1.0: ttyACM0: USB ACM device
Jun 30 23:58:35 noteb00k kernel: /w/work/lesh/research/driver/cdc-acm.c: acm_control_msg: rq: 0x22 val: 0x0 len: 0x0
result: 0
Jun 30 23:58:35 noteb00k kernel: /w/work/lesh/research/driver/cdc-acm.c: acm_control_msg: rq: 0x20 val: 0x0 len: 0x7
result: 7
Jun 30 23:58:35 noteb00k kernel: usb 2-3: adding 2-3:1.1 (config #1, interface 1)
Jun 30 23:58:35 noteb00k kernel: usb 2-3:1.1: uevent
Jun 30 23:58:35 noteb00k kernel: hub 2-0:1.0: state 7 ports 3 chg 0000 evt 0008
Jun 30 23:58:38 noteb00k kernel: hub 1-0:1.0: hub_suspend
Jun 30 23:58:38 noteb00k kernel: usb usb1: bus auto-suspend
Jun 30 23:58:38 noteb00k kernel: ehci_hcd 0000:00:03.3: suspend root hub

======================== echo -n S >/dev/ttyACM0 ========================
Jun 30 23:58:44 noteb00k kernel: /w/work/lesh/research/driver/cdc-acm.c: Entering acm_tty_open.
Jun 30 23:58:44 noteb00k kernel: /w/work/lesh/research/driver/cdc-acm.c: acm_control_msg: rq: 0x22 val: 0x3 len: 0x0
result: 0
Jun 30 23:58:44 noteb00k kernel: /w/work/lesh/research/driver/cdc-acm.c: Entering acm_tty_write to write 1 bytes,
Jun 30 23:58:44 noteb00k kernel: /w/work/lesh/research/driver/cdc-acm.c: Get 1 bytes...
Jun 30 23:58:44 noteb00k kernel: /w/work/lesh/research/driver/cdc-acm.c: acm_write_start susp_count: 0
Jun 30 23:58:44 noteb00k kernel: usb_sumbit_urb: failing due to non-positive interval //
Jun 30 23:58:44 noteb00k kernel: usb_submit_urb: xfertype = 3 of 1/3 // these were added by me
Jun 30 23:58:44 noteb00k kernel: xfertype is USB_ENDPOINT_XFER_INT //
Jun 30 23:58:44 noteb00k kernel: /w/work/lesh/research/driver/cdc-acm.c: usb_submit_urb(write bulk) failed: -22
Jun 30 23:58:44 noteb00k kernel: /w/work/lesh/research/driver/cdc-acm.c: Entering acm_rx_tasklet
Jun 30 23:58:44 noteb00k kernel: /w/work/lesh/research/driver/cdc-acm.c: acm_rx_tasklet: ACM not ready
Jun 30 23:58:44 noteb00k kernel: /w/work/lesh/research/driver/cdc-acm.c: acm_control_msg: rq: 0x22 val: 0x0 len: 0x0
result: 0
Jun 30 23:58:44 noteb00k kernel: /w/work/lesh/research/driver/cdc-acm.c: acm_ctrl_irq - urb shutting down with
status: -2

======================== cat /dev/ttyACM0 ========================
Jun 30 23:58:54 noteb00k kernel: /w/work/lesh/research/driver/cdc-acm.c: Entering acm_tty_open.
Jun 30 23:58:54 noteb00k kernel: /w/work/lesh/research/driver/cdc-acm.c: acm_control_msg: rq: 0x22 val: 0x3 len: 0x0
result: 0
Jun 30 23:58:54 noteb00k kernel: /w/work/lesh/research/driver/cdc-acm.c: Entering acm_rx_tasklet
Jun 30 23:58:54 noteb00k kernel: usb_sumbit_urb: failing due to non-positive interval
Jun 30 23:58:54 noteb00k kernel: usb_submit_urb: xfertype = 3 of 1/3
Jun 30 23:58:54 noteb00k kernel: xfertype is USB_ENDPOINT_XFER_INT
Jun 30 23:58:54 noteb00k kernel: /w/work/lesh/research/driver/cdc-acm.c: input control lines: dcd- dsr- break- ring-
framing- parity- overrun-
Jun 30 23:58:54 noteb00k kernel: /w/work/lesh/research/driver/cdc-acm.c: disconnected from network

======================== Terminate cat with Ctrl+C ========================
Jun 30 23:58:58 noteb00k kernel: /w/work/lesh/research/driver/cdc-acm.c: acm_control_msg: rq: 0x22 val: 0x0 len: 0x0
result: 0
Jun 30 23:58:58 noteb00k kernel: /w/work/lesh/research/driver/cdc-acm.c: acm_ctrl_irq - urb shutting down with
status:-2

======================== Device unplugged ========================
Jun 30 23:59:08 noteb00k kernel: hub 2-0:1.0: state 7 ports 3 chg 0000 evt 0008
Jun 30 23:59:08 noteb00k kernel: ohci_hcd 0000:00:03.0: GetStatus roothub.portstatus [2] = 0x00030300 PESC CSC LSDA
PPS
Jun 30 23:59:08 noteb00k kernel: hub 2-0:1.0: port 3, status 0300, change 0003, 1.5 Mb/s
Jun 30 23:59:08 noteb00k kernel: usb 2-3: USB disconnect, address 5
Jun 30 23:59:08 noteb00k kernel: usb 2-3: unregistering device
Jun 30 23:59:08 noteb00k kernel: usb 2-3: usb_disable_device nuking all URBs
Jun 30 23:59:08 noteb00k kernel: usb 2-3: unregistering interface 2-3:1.0
Jun 30 23:59:08 noteb00k kernel: /w/work/lesh/research/driver/cdc-acm.c: Entering stop_data_traffic
Jun 30 23:59:08 noteb00k kernel: usb 2-3:1.0: uevent
Jun 30 23:59:08 noteb00k kernel: usb 2-3: unregistering interface 2-3:1.1
Jun 30 23:59:08 noteb00k kernel: usb 2-3:1.1: uevent
Jun 30 23:59:08 noteb00k kernel: usb 2-3: uevent
Jun 30 23:59:08 noteb00k kernel: hub 2-0:1.0: debounce: port 3: total 100ms stable 100ms status 0x300
Jun 30 23:59:09 noteb00k kernel: ohci_hcd 0000:00:03.0: auto-stop root hub
Jun 30 23:59:11 noteb00k kernel: hub 2-0:1.0: hub_suspend
Jun 30 23:59:11 noteb00k kernel: usb usb2: bus auto-suspend
Jun 30 23:59:11 noteb00k kernel: ohci_hcd 0000:00:03.0: suspend root hub

Attachment: signature.asc
Description: This is a digitally signed message part.