kern/48237: NetBSD 6.1 failed to detect USB 1.x full-speed device (umodem)

To: kern-bug-people%netbsd.org@localhost,gnats-admin%netbsd.org@localhost,netbsd-bugs%netbsd.org@localhost
Subject: kern/48237: NetBSD 6.1 failed to detect USB 1.x full-speed device (umodem)
From: Wolfgang.Stukenbrock%nagler-company.com@localhost
Date: Tue, 24 Sep 2013 10:35:00 +0000 (UTC)
>Number:         48237
>Category:       kern
>Synopsis:       NetBSD 6.1 failed to detect USB 1.x full-speed device (umodem)
>Confidential:   no
>Severity:       serious
>Priority:       high
>Responsible:    kern-bug-people
>State:          open
>Class:          sw-bug
>Submitter-Id:   net
>Arrival-Date:   Tue Sep 24 10:35:00 +0000 2013
>Originator:     Dr. Wolfgang Stukenbrock
>Release:        NetBSD 6.1
>Organization:
Dr. Nagler & Company GmbH
>Environment:
        
        
System: NetBSD test-s0 5.1.2 NetBSD 5.1.2 (NSW-WS) #3: Fri Dec 21 15:15:43 CET 
2012 wgstuken@test-s0:/usr/src/sys/arch/amd64/compile/NSW-WS amd64
Architecture: x86_64
Machine: amd64
>Description:
        In 5.x every thing was fine.
        Now in 6.1 (I think 6.x is affected) our old USB-modem devices are no
        longer detected.
        E.g. 'uhub1: device problem, disabling port 2' is reported - the hub
        and the port number vary depending on the connection.
        The Modem is an "old" full-speed device according to the hand-over
        message from the ehci.
        A Mouse (low-speed device) is detected correctly.
        'uhidev0: Microsoft Microsoft 5-Button Mouse with IntelliEye(TM), rev 
1.10/3.00, addr 2, iclass 3/1'
        I've enabled some debugging, but I don't understand the output.
        The main problem when enabling USB_DBUG is,
        that the serial console is to slow, so everything seems to run into
        timeout and nothing connects anymore ...
        I've tried USB_DEBUG, but commented out UHCI_DEBUG in usb.h.
        Now the mouse is attached again and the output below is on console if
        on modem is connected.

        If anybody can tell me what to do for additional debugging I'm willing
        to do it, but I need some help with this.
>How-To-Repeat:
        Setup 6.1 and connect an USB 1.0 device like
        'Lucent Technologies, Inc. ELSA Modem Board, rev 1.00/1.00'
        At least this type of device is not detected correctly.
>Fix:
        not realy known till now.
        The fix mentioned in PR 46696 discusion (even if expanded to full-speed
        devices or all devices) does not solve the problem.
        I'm not shure what is gooing on, but for USB 1.x devices the initial 
packet
        may not exceed 8 Bytes as far as I know, so the 64-Byte change should 
never
        reach USB 1.x devices. So the check on the speed only (not the version)
        sounds like an incomplete way in PR 46696 ...


        Added output from connection try:
usb_transfer_complete: pipe=0xc1729ccc xfer=0xc14da2b4 status=0 actlen=1
usb_transfer_complete: repeat=1 new head=0xc14da2b4
uhub_intr: sc=0xc165f4a8
usb_needs_explore
usb_event_thread: woke up
usb_discover
uhub_explore dev=0xc1693a0c addr=1
usbd_alloc_xfer() = 0xc1757e1c
usbd_transfer: xfer=0xc1757e1c, flags=0x2, pipe=0xc1729f6c, running=0
usbd_dump_queue: pipe=0xc1729f6c
usb_allocmem: use frag=0xd99e2d80 size=4
usb_insert_transfer: pipe=0xc1729f6c running=0 timeout=5000
usb_transfer_complete: pipe=0xc1729f6c xfer=0xc1757e1c status=0 actlen=4
usb_freemem: frag=0xd99e2d80
usb_transfer_complete: repeat=0 new head=0x0
usbd_start_next: pipe=0xc1729f6c, xfer=0x0
usbd_free_xfer: 0xc1757e1c
uhub_explore: status change hub=1 port=2
usbd_alloc_xfer() = 0xc1757e1c
usbd_transfer: xfer=0xc1757e1c, flags=0x2, pipe=0xc1729f6c, running=0
usbd_dump_queue: pipe=0xc1729f6c
usb_insert_transfer: pipe=0xc1729f6c running=0 timeout=5000
usb_transfer_complete: pipe=0xc1729f6c xfer=0xc1757e1c status=0 actlen=0
usb_transfer_complete: repeat=0 new head=0x0
usbd_start_next: pipe=0xc1729f6c, xfer=0x0
usbd_free_xfer: 0xc1757e1c
uhub_explore: port=2 !CURRENT_CONNECT_STATUS
usb_transfer_complete: pipe=0xc171c514 xfer=0xc14da014 status=0 actlen=2
usb_transfer_complete: repeat=1 new head=0xc14da014
uhub_intr: sc=0xc165f390
usb_needs_explore
usb_needs_explore
usb_event_thread: woke up
usb_discover
uhub_explore dev=0xc169388c addr=1
usbd_alloc_xfer() = 0xc1757b7c
usbd_transfer: xfer=0xc1757b7c, flags=0x2, pipe=0xc171cc34, running=0
usbd_dump_queue: pipe=0xc171cc34
usb_allocmem: use frag=0xd99e2d80 size=4
usb_insert_transfer: pipe=0xc171cc34 running=0 timeout=5000
usb_transfer_complete: pipe=0xc171cc34 xfer=0xc1757b7c status=0 actlen=4
usb_freemem: frag=0xd99e2d80
usb_transfer_complete: repeat=0 new head=0x0
usbd_start_next: pipe=0xc171cc34, xfer=0x0
usbd_free_xfer: 0xc1757b7c
uhub_explore: status change hub=1 port=4
usbd_alloc_xfer() = 0xc1757b7c
usbd_transfer: xfer=0xc1757b7c, flags=0x2, pipe=0xc171cc34, running=0
usbd_dump_queue: pipe=0xc171cc34
usb_insert_transfer: pipe=0xc171cc34 running=0 timeout=5000
usb_transfer_complete: pipe=0xc171cc34 xfer=0xc1757b7c status=0 actlen=0
usb_transfer_complete: repeat=0 new head=0x0
usbd_start_next: pipe=0xc171cc34, xfer=0x0
usbd_free_xfer: 0xc1757b7c
usb_event_thread: woke up
usb_discover
usbd_alloc_xfer() = 0xc1757b7c
usbd_transfer: xfer=0xc1757b7c, flags=0x2, pipe=0xc171cc34, running=0
usbd_dump_queue: pipe=0xc171cc34
usb_insert_transfer: pipe=0xc171cc34 running=0 timeout=5000
usb_event_thread: woke up
usb_discover
ehci0: handing over full speed device on port 4 to uhci1
usb_transfer_complete: pipe=0xc171cc34 xfer=0xc1757b7c status=0 actlen=0
usb_transfer_complete: pipe=0xc171c514 xfer=0xc14da014 status=0 actlen=2
usb_transfer_complete: repeat=1 new head=0xc14da014
uhub_intr: sc=0xc165f390
usb_needs_explore
usb_transfer_complete: repeat=0 new head=0x0
usbd_start_next: pipe=0xc171cc34, xfer=0x0
usbd_free_xfer: 0xc1757b7c
usbd_alloc_xfer() = 0xc1757b7c
usbd_transfer: xfer=0xc1757b7c, flags=0x2, pipe=0xc171cc34, running=0
usbd_dump_queue: pipe=0xc171cc34
usb_allocmem: use frag=0xd99e2d80 size=4
usb_insert_transfer: pipe=0xc171cc34 running=0 timeout=5000
usb_transfer_complete: pipe=0xc171cc34 xfer=0xc1757b7c status=0 actlen=4
usb_freemem: frag=0xd99e2d80
usb_transfer_complete: repeat=0 new head=0x0
usbd_start_next: pipe=0xc171cc34, xfer=0x0
usb_transfer_complete: pipe=0xc1729ccc xfer=0xc14da2b4 status=0 actlen=1
usb_transfer_complete: repeat=1 new head=0xc14da2b4
uhub_intr: sc=0xc165f4a8
usb_needs_explore
usbd_free_xfer: 0xc1757b7c
usbd_alloc_xfer() = 0xc1757b7c
usbd_transfer: xfer=0xc1757b7c, flags=0x2, pipe=0xc171cc34, running=0
usbd_dump_queue: pipe=0xc171cc34
usb_allocmem: use frag=0xd99e2d80 size=4
usb_insert_transfer: pipe=0xc171cc34 running=0 timeout=5000
usb_transfer_complete: pipe=0xc171cc34 xfer=0xc1757b7c status=0 actlen=4
usb_freemem: frag=0xd99e2d80
usb_transfer_complete: repeat=0 new head=0x0
usbd_start_next: pipe=0xc171cc34, xfer=0x0
usbd_free_xfer: 0xc1757b7c
uhub_explore dev=0xc169388c addr=1
usbd_alloc_xfer() = 0xc1757b7c
usbd_transfer: xfer=0xc1757b7c, flags=0x2, pipe=0xc171cc34, running=0
usbd_dump_queue: pipe=0xc171cc34
usb_allocmem: use frag=0xd99e2d80 size=4
usb_insert_transfer: pipe=0xc171cc34 running=0 timeout=5000
usb_transfer_complete: pipe=0xc171cc34 xfer=0xc1757b7c status=0 actlen=4
usb_freemem: frag=0xd99e2d80
usb_transfer_complete: repeat=0 new head=0x0
usbd_start_next: pipe=0xc171cc34, xfer=0x0
usbd_free_xfer: 0xc1757b7c
uhub_explore: status change hub=1 port=4
usb_transfer_complete: pipe=0xc1729ccc xfer=0xc14da2b4 status=0 actlen=1
usb_transfer_complete: repeat=1 new head=0xc14da2b4
uhub_intr: sc=0xc165f4a8
usbd_alloc_xfer() = 0xc1757b7c
usbd_transfer: xfer=0xc1757b7c, flags=0x2, pipe=0xc171cc34, running=0
usbd_dump_queue: pipe=0xc171cc34
usb_insert_transfer: pipe=0xc171cc34 running=0 timeout=5000
usb_transfer_complete: pipe=0xc171cc34 xfer=0xc1757b7c status=0 actlen=0
usb_transfer_complete: repeat=0 new head=0x0
usbd_start_next: pipe=0xc171cc34, xfer=0x0
usbd_free_xfer: 0xc1757b7c
uhub_explore: port=4 !CURRENT_CONNECT_STATUS
usb_event_thread: woke up
usb_discover
uhub_explore dev=0xc1693a0c addr=1
usbd_alloc_xfer() = 0xc1757e1c
usbd_transfer: xfer=0xc1757e1c, flags=0x2, pipe=0xc1729f6c, running=0
usbd_dump_queue: pipe=0xc1729f6c
usb_allocmem: use frag=0xd99e2d80 size=4
usb_insert_transfer: pipe=0xc1729f6c running=0 timeout=5000
usb_transfer_complete: pipe=0xc1729f6c xfer=0xc1757e1c status=0 actlen=4
usb_freemem: frag=0xd99e2d80
usb_transfer_complete: repeat=0 new head=0x0
usbd_start_next: pipe=0xc1729f6c, xfer=0x0
usbd_free_xfer: 0xc1757e1c
uhub_explore: status change hub=1 port=2
usbd_alloc_xfer() = 0xc1757e1c
usb_transfer_complete: pipe=0xc1729ccc xfer=0xc14da2b4 status=0 actlen=1
usb_transfer_complete: repeat=1 new head=0xc14da2b4
uhub_intr: sc=0xc165f4a8
usbd_transfer: xfer=0xc1757e1c, flags=0x2, pipe=0xc1729f6c, running=0
usbd_dump_queue: pipe=0xc1729f6c
usb_insert_transfer: pipe=0xc1729f6c running=0 timeout=5000
usb_transfer_complete: pipe=0xc1729f6c xfer=0xc1757e1c status=0 actlen=0
usb_transfer_complete: repeat=0 new head=0x0
usbd_start_next: pipe=0xc1729f6c, xfer=0x0
usbd_free_xfer: 0xc1757e1c
usbd_alloc_xfer() = 0xc1757e1c
usbd_transfer: xfer=0xc1757e1c, flags=0x2, pipe=0xc1729f6c, running=0
usbd_dump_queue: pipe=0xc1729f6c
usb_insert_transfer: pipe=0xc1729f6c running=0 timeout=5000
usb_transfer_complete: pipe=0xc1729ccc xfer=0xc14da2b4 status=0 actlen=1
usb_transfer_complete: repeat=1 new head=0xc14da2b4
uhub_intr: sc=0xc165f4a8
usb_transfer_complete: pipe=0xc1729f6c xfer=0xc1757e1c status=0 actlen=0
usb_transfer_complete: repeat=0 new head=0x0
usbd_start_next: pipe=0xc1729f6c, xfer=0x0
usbd_free_xfer: 0xc1757e1c
usbd_alloc_xfer() = 0xc1757e1c
usbd_transfer: xfer=0xc1757e1c, flags=0x2, pipe=0xc1729f6c, running=0
usbd_dump_queue: pipe=0xc1729f6c
usb_allocmem: use frag=0xd99e2d80 size=4
usb_insert_transfer: pipe=0xc1729f6c running=0 timeout=5000
usb_transfer_complete: pipe=0xc1729f6c xfer=0xc1757e1c status=0 actlen=4
usb_freemem: frag=0xd99e2d80
usb_transfer_complete: repeat=0 new head=0x0
usbd_start_next: pipe=0xc1729f6c, xfer=0x0
usbd_free_xfer: 0xc1757e1c
usbd_alloc_xfer() = 0xc1757e1c
usbd_transfer: xfer=0xc1757e1c, flags=0x2, pipe=0xc1729f6c, running=0
usbd_dump_queue: pipe=0xc1729f6c
usb_insert_transfer: pipe=0xc1729f6c running=0 timeout=5000
usb_transfer_complete: pipe=0xc1729f6c xfer=0xc1757e1c status=0 actlen=0
usb_transfer_complete: repeat=0 new head=0x0
usbd_start_next: pipe=0xc1729f6c, xfer=0x0
usbd_free_xfer: 0xc1757e1c
usbd_alloc_xfer() = 0xc1757e1c
usbd_transfer: xfer=0xc1757e1c, flags=0x2, pipe=0xc1729f6c, running=0
usbd_dump_queue: pipe=0xc1729f6c
usb_allocmem: use frag=0xd99e2d80 size=4
usb_insert_transfer: pipe=0xc1729f6c running=0 timeout=5000
usb_transfer_complete: pipe=0xc1729f6c xfer=0xc1757e1c status=0 actlen=4
usb_freemem: frag=0xd99e2d80
usb_transfer_complete: repeat=0 new head=0x0
usbd_start_next: pipe=0xc1729f6c, xfer=0x0
usbd_free_xfer: 0xc1757e1c
usbd_new_device bus=0xc169200c port=2 depth=1 speed=2
usb_allocmem: use frag=0xd99e2d80 size=8
usbd_alloc_xfer() = 0xc1757e1c
usbd_transfer: xfer=0xc1757e1c, flags=0x6, pipe=0xc17294ec, running=0
usbd_dump_queue: pipe=0xc17294ec
usb_allocmem: use frag=0xd99e2d40 size=64
usb_insert_transfer: pipe=0xc17294ec running=0 timeout=5000
usb_schedsoftintr: polling=0
usb_transfer_complete: pipe=0xc17294ec xfer=0xc1757e1c status=0 actlen=18
usb_freemem: frag=0xd99e2d40
usb_transfer_complete: repeat=0 new head=0x0
usbd_start_next: pipe=0xc17294ec, xfer=0x0
usbd_free_xfer: 0xc1757e1c
ini-desc 0 actlen 18
usbd_alloc_xfer() = 0xc1757e1c
usbd_transfer: xfer=0xc1757e1c, flags=0x2, pipe=0xc1729f6c, running=0
usbd_dump_queue: pipe=0xc1729f6c
usb_insert_transfer: pipe=0xc1729f6c running=0 timeout=5000
usb_transfer_complete: pipe=0xc1729f6c xfer=0xc1757e1c status=0 actlen=0
usb_transfer_complete: repeat=0 new head=0x0
usbd_start_next: pipe=0xc1729f6c, xfer=0x0
usbd_free_xfer: 0xc1757e1c
usbd_alloc_xfer() = 0xc1757e1c
usbd_transfer: xfer=0xc1757e1c, flags=0x2, pipe=0xc1729f6c, running=0
usbd_dump_queue: pipe=0xc1729f6c
usb_allocmem: use frag=0xd99e2d40 size=4
usb_insert_transfer: pipe=0xc1729f6c running=0 timeout=5000
usb_transfer_complete: pipe=0xc1729f6c xfer=0xc1757e1c status=0 actlen=4
usb_freemem: frag=0xd99e2d40
usb_transfer_complete: repeat=0 new head=0x0
usbd_start_next: pipe=0xc1729f6c, xfer=0x0
usbd_free_xfer: 0xc1757e1c
usbd_alloc_xfer() = 0xc1757e1c
usbd_transfer: xfer=0xc1757e1c, flags=0x2, pipe=0xc1729f6c, running=0
usbd_dump_queue: pipe=0xc1729f6c
usb_insert_transfer: pipe=0xc1729f6c running=0 timeout=5000
usb_transfer_complete: pipe=0xc1729f6c xfer=0xc1757e1c status=0 actlen=0
usb_transfer_complete: repeat=0 new head=0x0
usbd_start_next: pipe=0xc1729f6c, xfer=0x0
usbd_free_xfer: 0xc1757e1c
usbd_new_device: adding unit addr=2, rev=100, class=2, subclass=0, protocol=0, 
maxpacket=8, len=18, speed=2
usbd_alloc_xfer() = 0xc1757e1c
usbd_transfer: xfer=0xc1757e1c, flags=0x2, pipe=0xc17294ec, running=0
usbd_dump_queue: pipe=0xc17294ec
usb_insert_transfer: pipe=0xc17294ec running=0 timeout=5000
usb_schedsoftintr: polling=0
usb_transfer_complete: pipe=0xc17294ec xfer=0xc1757e1c status=0 actlen=0
usb_transfer_complete: repeat=0 new head=0x0
usbd_start_next: pipe=0xc17294ec, xfer=0x0
usbd_free_xfer: 0xc1757e1c
usbd_alloc_xfer() = 0xc1757e1c
usbd_transfer: xfer=0xc1757e1c, flags=0x2, pipe=0xc17294ec, running=0
usbd_dump_queue: pipe=0xc17294ec
usb_allocmem: use frag=0xd99e2d40 size=18
usb_insert_transfer: pipe=0xc17294ec running=0 timeout=5000
usb_schedsoftintr: polling=0
usb_transfer_complete: pipe=0xc17294ec xfer=0xc1757e1c status=17 actlen=0
usb_freemem: frag=0xd99e2d40
usb_transfer_complete: repeat=0 new head=0x0
usbd_start_next: pipe=0xc17294ec, xfer=0x0
usbd_transfer: xfer=0xc1757e1c, flags=0x2, pipe=0xc17294ec, running=0
usbd_dump_queue: pipe=0xc17294ec
usb_allocmem: use frag=0xd99e2d40 size=2
usb_insert_transfer: pipe=0xc17294ec running=0 timeout=5000
usb_schedsoftintr: polling=0
usb_transfer_complete: pipe=0xc17294ec xfer=0xc1757e1c status=17 actlen=0
usb_freemem: frag=0xd99e2d40
usb_transfer_complete: repeat=0 new head=0x0
usbd_start_next: pipe=0xc17294ec, xfer=0x0
usbd_do_request_flags_pipe: returning err=STALLED
usbd_free_xfer: 0xc1757e1c
usbd_remove_device: 0xc1ff698c
usbd_ar_pipe: pipe=0xc17294ec
usbd_dump_queue: pipe=0xc17294ec
uhub_explore: usbd_new_device failed, error=STALLED
uhub1: device problem, disabling port 2
usbd_alloc_xfer() = 0xc1757e1c
usbd_transfer: xfer=0xc1757e1c, flags=0x2, pipe=0xc1729f6c, running=0
usbd_dump_queue: pipe=0xc1729f6c
usb_insert_transfer: pipe=0xc1729f6c running=0 timeout=5000
usb_transfer_complete: pipe=0xc1729f6c xfer=0xc1757e1c status=0 actlen=0
usb_transfer_complete: repeat=0 new head=0x0
usbd_start_next: pipe=0xc1729f6c, xfer=0x0
usbd_free_xfer: 0xc1757e1c
usb_event_thread: woke up
usb_discover

>Unformatted:
Follow-Ups:
- Re: kern/48237: NetBSD 6.1 failed to detect USB 1.x full-speed device (umodem)
  - From: Nick Hudson
Prev by Date: kern/48236: iavc driver crashes during initialisation
Next by Date: Re: kern/48237: NetBSD 6.1 failed to detect USB 1.x full-speed device (umodem)
Previous by Thread: kern/48236: iavc driver crashes during initialisation
Next by Thread: Re: kern/48237: NetBSD 6.1 failed to detect USB 1.x full-speed device (umodem)
Indexes:
Home | Main Index | Thread Index | Old Index