USB Serial device disconnect causes IRQ disable

USB Serial device disconnect causes IRQ disable

[amruth]

Hi
I again encountered the same issue IRQ23 disabled.
Here is my /proc/interrupts
           CPU0       CPU1       
  0:        381          0   IO-APIC-edge      timer
  1:         47       6499   IO-APIC-edge      i8042
  3:          2          0   IO-APIC-edge    
  4:          4          0   IO-APIC-edge    
  6:          7          0   IO-APIC-edge      floppy
  9:          0          0   IO-APIC-fasteoi   acpi
 12:          4          0   IO-APIC-edge      i8042
 14:      27742          0   IO-APIC-edge      ide0
 15:       3152     809663   IO-APIC-edge      ide1
 16:        383          0   IO-APIC-fasteoi   uhci_hcd:usb2, uhci_hcd:usb5
 18:     888468          0   IO-APIC-fasteoi   ata_piix, uhci_hcd:usb4, eth0
 19:        268          0   IO-APIC-fasteoi   uhci_hcd:usb3
 23:     300001          0   IO-APIC-fasteoi   ehci_hcd:usb1
NMI:        436        172   Non-maskable interrupts
LOC:    1810724    1760209   Local timer interrupts
RES:     171199     167417   Rescheduling interrupts
CAL:        140       6288   function call interrupts
TLB:       4071       1963   TLB shootdowns
TRM:          0          0   Thermal event interrupts
SPU:          0          0   Spurious interrupts
ERR:          0
MIS:          0

Thanks
Amruth p.v


--- On Thu, 8/7/08, Oliver Neukum <oliver@neukum.org> wrote:

> From: Oliver Neukum <oliver@neukum.org>
> Subject: Re: USB Serial device disconnect causes IRQ disable
> To: "amruth" <amruth_pv@yahoo.com>
> Cc: linux-usb@vger.kernel.org
> Date: Thursday, August 7, 2008, 3:10 AM
> Am Mittwoch 06 August 2008 22:58:08 schrieb amruth:
> > Hi
> > All
> > After disconnecting the usb serial device randomly. I
> am getting the following error.
> > 
> > usr/src/linux-2.6.26/drivers/usb/serial/usb-serial.c:
> serial is OK
> > /usr/src/linux-2.6.26/drivers/usb/serial/usb-serial.c:
> after rteturn serial
> > /usr/src/linux-2.6.26/drivers/usb/serial/usb-serial.c:
> before unregister serial
> > magtek ttyUSB0: Magtek 75/Excella USB card reader
> converter now disconnected from ttyUSB0
> > /usr/src/linux-2.6.26/drivers/usb/serial/usb-serial.c:
> port_release - ttyUSB0
> > /usr/src/linux-2.6.26/drivers/usb/serial/usb-serial.c:
> after unregister serial
> 
> If you have a spurious interrupt sharing a line with a
> legitimate source
> of interrupts, you'll see nothing while the legitimate
> source operates.
> Is there another device sharing irq 23? What does
> /proc/interrupts say?
> 
> 	Regards
> 		Oliver


      

Re: USB Serial device disconnect causes IRQ disable

[Oliver Neukum]

Am Mittwoch 20 August 2008 21:34:51 schrieb amruth:
> Hi
> I again encountered the same issue IRQ23 disabled.
> Here is my /proc/interrupts

There is some unknown interrupt on 23. Try unloading
drivers until it works. You can sort of bisect it if you divide
your loaded modules in groups.

	Regards
		Oliver

USB Serial device disconnect causes IRQ disable

[amruth]

Hi
I don't have any driver modules. I have everything built into kernel.
When can this kind of IRQ disable happen, what causes this. The issue happened because of hotplugging my device but the device works fine.
usb_register(driver) might have caused the issue. How do we debug this problem.
Thanks
Amruth p.v


--- On Wed, 8/20/08, Oliver Neukum <oliver@neukum.org> wrote:

> From: Oliver Neukum <oliver@neukum.org>
> Subject: Re: USB Serial device disconnect causes IRQ disable
> To: amruth_pv@yahoo.com
> Cc: linux-usb@vger.kernel.org, linux-kernel@vger.kernel.org
> Date: Wednesday, August 20, 2008, 3:23 PM
> Am Mittwoch 20 August 2008 21:34:51 schrieb amruth:
> > Hi
> > I again encountered the same issue IRQ23 disabled.
> > Here is my /proc/interrupts
> 
> There is some unknown interrupt on 23. Try unloading
> drivers until it works. You can sort of bisect it if you
> divide
> your loaded modules in groups.
> 
> 	Regards
> 		Oliver
> --
> To unsubscribe from this list: send the line
> "unsubscribe linux-kernel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at 
> http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at  http://www.tux.org/lkml/


      

Re: USB Serial device disconnect causes IRQ disable

[Oliver Neukum]

Am Donnerstag 21 August 2008 02:18:37 schrieb amruth:
> Hi
> I don't have any driver modules. I have everything built into kernel.
> When can this kind of IRQ disable happen, what causes this. The issue happened because of hotplugging my device but the device works fine.
> usb_register(driver) might have caused the issue. How do we debug this problem.

What happens when you never plug in the device?
I think you have another device causing interrupts whose driver
doesn't handle them. While the usb host controller is busy due
to your device, it generates enough interrupts to keep the logic
for detection of spurious interrupts happy. When you unplug your
device you get too many unhandled interrupts.

	Regards
		Oliver

USB Serial device disconnect causes IRQ disable

[amruth]

Hi
Oliver

> What happens when you never plug in the device?
Everything works fine without plugging the device. I have memory stick 
which never creates any problem.

> I think you have another device causing interrupts whose
> driver doesn't handle them. While the usb host controller is
> busy due to your device, it generates enough interrupts to keep the
> logic for detection of spurious interrupts happy. When you unplug
> your device you get too many unhandled interrupts.

I understand the problem because I have 2 devices using the same driver.
One device requies only to read from bulk in pipe and other gets null packet interrupt followed by bulk in read to get data.

Previously I did only bulk in read for both the devices and no handler for interrupt.
When I use together, there is flooding of interrupts coming from the device but unhandled by the driver.

I need to separate out both the logics one for interrupt the other to get bulk pipe to read data directly.

Thanks Oliver for pointing the issue, I never understood why it happened but I see the data being read from bulk in pipe irrespective of handling interrupts which means we need to read interrupts otherwise spurious interrupts logic detects it and disables the USB bus 

I have another issue where I need to stop the bulk in read callback when it no longer has data to give to the application because the data length is dynamic. I see that we continue to read without even data in the urb.

 /* Continue to read if we have still urbs to do. */
                    port->read_urb->dev = port->serial->dev;
                 result = usb_submit_urb(port->read_urb, GFP_ATOMIC);
                 if (result)
                         err("%s - failed resubmitting read urb, error %d", __FUNCTION__, result);
                 dbg("%s - usb_submit_urb(read urb)", __FUNCTION__);

This logic is used in all drivers.
After close is called in the application, the driver continues to call read_bulk_in callback  function which continues to read and the error
"failed resubmitting read urb" is displayed. 

This particular functions below in close does not kill read_urb and hence the bulk in call back continues to read.
                    usb_kill_urb(port->write_urb);
                    usb_kill_urb(port->read_urb);

How to effectively stop urbs submitting read request into USB when no longer data is ther in the transfer buffer.
Thanks
Amruth p.v


--- On Thu, 8/21/08, Oliver Neukum <oliver@neukum.org> wrote:

> From: Oliver Neukum <oliver@neukum.org>
> Subject: Re: USB Serial device disconnect causes IRQ disable
> To: amruth_pv@yahoo.com
> Cc: linux-usb@vger.kernel.org, linux-kernel@vger.kernel.org
> Date: Thursday, August 21, 2008, 12:19 AM
> Am Donnerstag 21 August 2008 02:18:37 schrieb amruth:
> > Hi
> > I don't have any driver modules. I have everything
> built into kernel.
> > When can this kind of IRQ disable happen, what causes
> this. The issue happened because of hotplugging my device
> but the device works fine.
> > usb_register(driver) might have caused the issue. How
> do we debug this problem.
> 
> What happens when you never plug in the device?
> I think you have another device causing interrupts whose
> driver
> doesn't handle them. While the usb host controller is
> busy due
> to your device, it generates enough interrupts to keep the
> logic
> for detection of spurious interrupts happy. When you unplug
> your
> device you get too many unhandled interrupts.
> 
> 	Regards
> 		Oliver
> --
> To unsubscribe from this list: send the line
> "unsubscribe linux-kernel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at 
> http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at  http://www.tux.org/lkml/


      

Re: USB Serial device disconnect causes IRQ disable

[Oliver Neukum]

Am Donnerstag 21 August 2008 08:03:57 schrieb amruth:
> > What happens when you never plug in the device?
> Everything works fine without plugging the device. I have memory stick 
> which never creates any problem.

OK, do you have any other USB device on the same bus as your serial
converter?

	Regards
		Oliver

USB Serial device disconnect causes IRQ disable

[amruth]

> OK, do you have any other USB device on the same bus as
> your serial
> converter?
I have one USB storage flash key device nothing else.
The problem is coming from serial convertor and my driver did not handle interrupts.

Thanks
Amruth p.v


--- On Thu, 8/21/08, Oliver Neukum <oliver@neukum.org> wrote:

> From: Oliver Neukum <oliver@neukum.org>
> Subject: Re: USB Serial device disconnect causes IRQ disable
> To: amruth_pv@yahoo.com
> Cc: linux-usb@vger.kernel.org, linux-kernel@vger.kernel.org
> Date: Thursday, August 21, 2008, 1:09 AM
> Am Donnerstag 21 August 2008 08:03:57 schrieb amruth:
> > > What happens when you never plug in the device?
> > Everything works fine without plugging the device. I
> have memory stick 
> > which never creates any problem.
> 
> OK, do you have any other USB device on the same bus as
> your serial
> converter?
> 
> 	Regards
> 		Oliver
> 
> --
> To unsubscribe from this list: send the line
> "unsubscribe linux-kernel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at 
> http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at  http://www.tux.org/lkml/


      

Re: USB Serial device disconnect causes IRQ disable

[Oliver Neukum]

Am Donnerstag 21 August 2008 08:18:38 schrieb amruth:
> > OK, do you have any other USB device on the same bus as
> > your serial
> > converter?
> I have one USB storage flash key device nothing else.
> The problem is coming from serial convertor and my driver did not handle interrupts.

But is this key on the same bus? What does "lsusb -t" say?
Your driver is USB, isn't it? It cannot fail to handle PCI interrupts.
There may be something fishy here.

	Regards
		Oliver

USB Serial device disconnect causes IRQ disable details captured

[amruth]

Hi
Oliver
I got the same issue once again. I have captured detail log and lusb -t with interrupts.
cat /proc/interrupts:

          CPU0       CPU1
  0:         86          0   IO-APIC-edge      timer
  1:       2355          0   IO-APIC-edge      i8042
  3:          2          0   IO-APIC-edge
  4:          4          0   IO-APIC-edge
  6:          7          0   IO-APIC-edge      floppy
  9:          0          0   IO-APIC-fasteoi   acpi
 12:          4          0   IO-APIC-edge      i8042
 14:      13715          0   IO-APIC-edge      ide0
 15:      33574          0   IO-APIC-edge      ide1
 16:        598          0   IO-APIC-fasteoi   uhci_hcd:usb2, uhci_hcd:usb5
 18:          5          0   IO-APIC-fasteoi   ata_piix, uhci_hcd:usb4
 19:         52          0   IO-APIC-fasteoi   uhci_hcd:usb3
 23:        326     199675   IO-APIC-fasteoi   ehci_hcd:usb1
NMI:          0          0   Non-maskable interrupts
LOC:      77657     131843   Local timer interrupts
RES:      14882      15086   Rescheduling interrupts
CAL:        136        490   function call interrupts
TLB:      10750       2825   TLB shootdowns
TRM:          0          0   Thermal event interrupts
SPU:          0          0   Spurious interrupts
ERR:          0
MIS:          0

lsusb -t:
Bus#  5
`-Dev#   1 Vendor 0x1d6b Product 0x0001
Bus#  4
`-Dev#   1 Vendor 0x1d6b Product 0x0001
Bus#  3
`-Dev#   1 Vendor 0x1d6b Product 0x0001
  `-Dev#   2 Vendor 0x413c Product 0x3010
Bus#  2
`-Dev#   1 Vendor 0x1d6b Product 0x0001
Bus#  1
`-Dev#   1 Vendor 0x1d6b Product 0x0002

dmesg:
sb 1-5: Magtek 75/Excella USB card reader converter now attached to ttyUSB1
drivers/usb/core/inode.c: creating file '012'
usb 1-5: New USB device found, idVendor=0801, idProduct=2231
usb 1-5: New USB device strings: Mfr=1, Product=2, SerialNumber=3
usb 1-5: Product: STX
usb 1-5: Manufacturer: MagTek
usb 1-5: SerialNumber: STX001
usb 2-2: uhci_result_common: failed with status 440000
/home/amr/linux-2.6.26/drivers/usb/serial/magtek.c: magtek_read_int_callback - p
ort 0
uhci_hcd 0000:00:1d.0: release dev 6 ep81-INT, period 8, phase 4, 61 us
hub 2-0:1.0: state 7 ports 2 chg 0000 evt 0004
uhci_hcd 0000:00:1d.0: port 2 portsc 008a,00
hub 2-0:1.0: port 2, status 0100, change 0003, 12 Mb/s
usb 2-2: USB disconnect, address 6
usb 2-2: unregistering device
usb 2-2: usb_disable_device nuking all URBs
usb 2-2: unregistering interface 2-2:1.0
/home/amr/linux-2.6.26/drivers/usb/serial/magtek.c: magtek_shutdown
magtek ttyUSB0: Magtek 75/Excella USB card reader converter now disconnected from ttyUSB0
magtek 2-2:1.0: device disconnected
usb 2-2:1.0: uevent
usb 2-2: uevent
hub 2-0:1.0: debounce: port 2: total 100ms stable 100ms status 0x100
usb usb2: suspend_rh (auto-stop)
ehci_hcd 0000:00:1d.7: devpath 5 ep2in 3strikes
/home/amr/linux-2.6.26/drivers/usb/serial/magtek.c: magtek_read_int_callback - port 1
usb 1-5: unlink qh0-00ff/dec56380 start 0 [1/0 us]
usb 1-5: link qh0-00ff/dec56380 start 0 [1/0 us]
usb 1-5: unlink qh0-00ff/dec56380 start 0 [1/0 us]
ehci_hcd 0000:00:1d.7: HC died; cleaning up
hub 1-0:1.0: state 0 ports 8 chg 0000 evt 0000
usb 1-4: USB disconnect, address 4
usb 1-4: unregistering device
usb 1-4: usb_disable_device nuking all URBs
usb 1-4: unregistering interface 1-4:1.0
usb 1-4:1.0: uevent
usb 1-4: uevent
usb 1-5: USB disconnect, address 12
usb 1-5: unregistering device
usb 1-4: usb_disable_device nuking all URBs
usb 1-4: unregistering interface 1-4:1.0
usb 1-4:1.0: uevent
usb 1-4: uevent
usb 1-5: USB disconnect, address 12
usb 1-5: unregistering device
usb 1-5: usb_disable_device nuking all URBs
usb 1-5: unregistering interface 1-5:1.0
/home/amr/linux-2.6.26/drivers/usb/serial/magtek.c: magtek_shutdown
magtek ttyUSB1: Magtek 75/Excella USB card reader converter now disconnected from ttyUSB1
magtek 1-5:1.0: device disconnected
usb 1-5:1.0: uevent
usb 1-5: uevent
irq 23: nobody cared (try booting with the "irqpoll" option)
Pid: 0, comm: swapper Not tainted 2.6.26kdbkgdb #1
 [<c0140300>] __report_bad_irq+0x2e/0x6f
 [<c0140514>] note_interrupt+0x1d3/0x207
 [<c013fa8a>] ? handle_IRQ_event+0x21/0x48
 [<c0140c3c>] handle_fasteoi_irq+0x8a/0xaa
 [<c010577e>] do_IRQ+0x71/0x8b
 [<c01024d4>] ? default_idle+0x0/0x42
 [<c010417b>] common_interrupt+0x23/0x28
 [<c01024d4>] ? default_idle+0x0/0x42
 [<c01024d4>] ? default_idle+0x0/0x42
 [<c0102405>] ? cpu_idle+0x4e/0xac
 [<c043ed6e>] start_secondary+0x156/0x15b
 =======================
handlers:
[<c0353bb7>] (usb_hcd_irq+0x0/0x58)
Disabling IRQ #23

Please let me know what might have caused this to fail.

Thanks
Amruth p.v


--- On Thu, 8/21/08, Oliver Neukum <oliver@neukum.org> wrote:

> From: Oliver Neukum <oliver@neukum.org>
> Subject: Re: USB Serial device disconnect causes IRQ disable
> To: amruth_pv@yahoo.com
> Cc: linux-usb@vger.kernel.org, linux-kernel@vger.kernel.org
> Date: Thursday, August 21, 2008, 1:28 AM
> Am Donnerstag 21 August 2008 08:18:38 schrieb amruth:
> > > OK, do you have any other USB device on the same
> bus as
> > > your serial
> > > converter?
> > I have one USB storage flash key device nothing else.
> > The problem is coming from serial convertor and my
> driver did not handle interrupts.
> 
> But is this key on the same bus? What does "lsusb
> -t" say?
> Your driver is USB, isn't it? It cannot fail to handle
> PCI interrupts.
> There may be something fishy here.
> 
> 	Regards
> 		Oliver
> --
> To unsubscribe from this list: send the line
> "unsubscribe linux-usb" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at 
> http://vger.kernel.org/majordomo-info.html


      

Re: USB Serial device disconnect causes IRQ disable details captured

[Alan Stern]

On Thu, 21 Aug 2008, amruth wrote:

> Hi
> Oliver
> I got the same issue once again. I have captured detail log and lusb -t with interrupts.
> cat /proc/interrupts:

> dmesg:
> sb 1-5: Magtek 75/Excella USB card reader converter now attached to ttyUSB1
> drivers/usb/core/inode.c: creating file '012'
> usb 1-5: New USB device found, idVendor=0801, idProduct=2231
> usb 1-5: New USB device strings: Mfr=1, Product=2, SerialNumber=3
> usb 1-5: Product: STX
> usb 1-5: Manufacturer: MagTek
> usb 1-5: SerialNumber: STX001
> usb 2-2: uhci_result_common: failed with status 440000
> /home/amr/linux-2.6.26/drivers/usb/serial/magtek.c: magtek_read_int_callback - p
> ort 0
> uhci_hcd 0000:00:1d.0: release dev 6 ep81-INT, period 8, phase 4, 61 us
> hub 2-0:1.0: state 7 ports 2 chg 0000 evt 0004
> uhci_hcd 0000:00:1d.0: port 2 portsc 008a,00
> hub 2-0:1.0: port 2, status 0100, change 0003, 12 Mb/s
> usb 2-2: USB disconnect, address 6
> usb 2-2: unregistering device
> usb 2-2: usb_disable_device nuking all URBs
> usb 2-2: unregistering interface 2-2:1.0
> /home/amr/linux-2.6.26/drivers/usb/serial/magtek.c: magtek_shutdown
> magtek ttyUSB0: Magtek 75/Excella USB card reader converter now disconnected from ttyUSB0
> magtek 2-2:1.0: device disconnected
> usb 2-2:1.0: uevent
> usb 2-2: uevent
> hub 2-0:1.0: debounce: port 2: total 100ms stable 100ms status 0x100
> usb usb2: suspend_rh (auto-stop)
> ehci_hcd 0000:00:1d.7: devpath 5 ep2in 3strikes
> /home/amr/linux-2.6.26/drivers/usb/serial/magtek.c: magtek_read_int_callback - port 1
> usb 1-5: unlink qh0-00ff/dec56380 start 0 [1/0 us]
> usb 1-5: link qh0-00ff/dec56380 start 0 [1/0 us]
> usb 1-5: unlink qh0-00ff/dec56380 start 0 [1/0 us]
> ehci_hcd 0000:00:1d.7: HC died; cleaning up

You should try using the patch in this message:

	http://marc.info/?l=linux-usb&m=121848784300960&w=2

If that doesn't help, can you test this on another computer to see if
the same thing happens?

For future testing, it would help if you enable CONFIG_PRINTK_TIME.

Alan Stern

USB Serial device disconnect causes IRQ disable details captured

[amruth]

Thanks Alan. I will test in another computers with the new patch and let you know if I again find the issue.

Thanks
Amruth p.v


--- On Thu, 8/21/08, Alan Stern <stern@rowland.harvard.edu> wrote:

> From: Alan Stern <stern@rowland.harvard.edu>
> Subject: Re: USB Serial device disconnect causes IRQ disable details captured
> To: "amruth" <amruth_pv@yahoo.com>
> Cc: "Oliver Neukum" <oliver@neukum.org>, linux-usb@vger.kernel.org, linux-kernel@vger.kernel.org
> Date: Thursday, August 21, 2008, 4:20 PM
> On Thu, 21 Aug 2008, amruth wrote:
> 
> > Hi
> > Oliver
> > I got the same issue once again. I have captured
> detail log and lusb -t with interrupts.
> > cat /proc/interrupts:
> 
> > dmesg:
> > sb 1-5: Magtek 75/Excella USB card reader converter
> now attached to ttyUSB1
> > drivers/usb/core/inode.c: creating file '012'
> > usb 1-5: New USB device found, idVendor=0801,
> idProduct=2231
> > usb 1-5: New USB device strings: Mfr=1, Product=2,
> SerialNumber=3
> > usb 1-5: Product: STX
> > usb 1-5: Manufacturer: MagTek
> > usb 1-5: SerialNumber: STX001
> > usb 2-2: uhci_result_common: failed with status 440000
> > /home/amr/linux-2.6.26/drivers/usb/serial/magtek.c:
> magtek_read_int_callback - p
> > ort 0
> > uhci_hcd 0000:00:1d.0: release dev 6 ep81-INT, period
> 8, phase 4, 61 us
> > hub 2-0:1.0: state 7 ports 2 chg 0000 evt 0004
> > uhci_hcd 0000:00:1d.0: port 2 portsc 008a,00
> > hub 2-0:1.0: port 2, status 0100, change 0003, 12 Mb/s
> > usb 2-2: USB disconnect, address 6
> > usb 2-2: unregistering device
> > usb 2-2: usb_disable_device nuking all URBs
> > usb 2-2: unregistering interface 2-2:1.0
> > /home/amr/linux-2.6.26/drivers/usb/serial/magtek.c:
> magtek_shutdown
> > magtek ttyUSB0: Magtek 75/Excella USB card reader
> converter now disconnected from ttyUSB0
> > magtek 2-2:1.0: device disconnected
> > usb 2-2:1.0: uevent
> > usb 2-2: uevent
> > hub 2-0:1.0: debounce: port 2: total 100ms stable
> 100ms status 0x100
> > usb usb2: suspend_rh (auto-stop)
> > ehci_hcd 0000:00:1d.7: devpath 5 ep2in 3strikes
> > /home/amr/linux-2.6.26/drivers/usb/serial/magtek.c:
> magtek_read_int_callback - port 1
> > usb 1-5: unlink qh0-00ff/dec56380 start 0 [1/0 us]
> > usb 1-5: link qh0-00ff/dec56380 start 0 [1/0 us]
> > usb 1-5: unlink qh0-00ff/dec56380 start 0 [1/0 us]
> > ehci_hcd 0000:00:1d.7: HC died; cleaning up
> 
> You should try using the patch in this message:
> 
> 	http://marc.info/?l=linux-usb&m=121848784300960&w=2
> 
> If that doesn't help, can you test this on another
> computer to see if
> the same thing happens?
> 
> For future testing, it would help if you enable
> CONFIG_PRINTK_TIME.
> 
> Alan Stern


      

USB Serial device disconnect causes IRQ disable not working after patch

[amruth]

Hi
Alan
The patch suggested by you did not work. I tried in another computer and found same issue. I have detailed log below.


[   44.761371] uhci_hcd 0000:00:1d.1: release dev 3 ep81-INT, period 8, phase 4, 93 us
[   46.568107] uhci_hcd 0000:00:1d.1: reserve dev 3 ep81-INT, period 8, phase 4, 93 us
[   46.569949] uhci_hcd 0000:00:1d.1: release dev 3 ep81-INT, period 8, phase 4, 93 us
[   46.570174] uhci_hcd 0000:00:1d.1: reserve dev 3 ep81-INT, period 8, phase 4, 93 us
[   46.570942] uhci_hcd 0000:00:1d.1: release dev 3 ep81-INT, period 8, phase 4, 93 us
[   47.576006] uhci_hcd 0000:00:1d.1: reserve dev 3 ep81-INT, period 8, phase 4, 93 us
[  112.460694] usbserial: USB Serial support registered for Magtek 75/Excella USB card reader
[  112.462710] usbcore: registered new interface driver magtek
[  112.463185] magtek: v1.01 Amruth Vamadev
[  112.463192] magtek: MAGTEK 75/Excella check USB Chipcard Reader Driver
[  143.041808] hub 1-0:1.0: state 7 ports 6 chg 0000 evt 0002
[  143.041808] ehci_hcd 0000:00:1d.7: GetStatus port 1 status 001803 POWER sig=j CSC CONNECT
[  143.041808] hub 1-0:1.0: port 1, status 0501, change 0001, 480 Mb/s
[  143.168024] hub 1-0:1.0: debounce: port 1: total 100ms stable 100ms status 0x501
[  143.224309] ehci_hcd 0000:00:1d.7: port 1 high speed
[  143.224323] ehci_hcd 0000:00:1d.7: GetStatus port 1 status 001005 POWER sig=se0 PE CONNECT
[  143.280021] usb 1-1: new high speed USB device using ehci_hcd and address 4
[  143.336281] ehci_hcd 0000:00:1d.7: port 1 high speed
[  143.336292] ehci_hcd 0000:00:1d.7: GetStatus port 1 status 001005 POWER sig=se0 PE CONNECT
[  143.412650] usb 1-1: default language 0x0409
[  143.413121] usb 1-1: uevent
[  143.417056] usb 1-1: usb_probe_device
[  143.417068] usb 1-1: configuration #1 chosen from 1 choice
[  143.417361] usb 1-1: adding 1-1:1.0 (config #1, interface 0)
[  143.417422] usb 1-1:1.0: uevent
[  143.417622] usbserial_generic 1-1:1.0: usb_probe_interface
[  143.417627] usbserial_generic 1-1:1.0: usb_probe_interface - got id
[  143.417646] magtek 1-1:1.0: usb_probe_interface
[  143.417650] magtek 1-1:1.0: usb_probe_interface - got id
[  143.417659] magtek 1-1:1.0: Magtek 75/Excella USB card reader converter detected
[  143.417669] drivers/usb/serial/magtek.c: magtek_startup
[  143.417800] usb 1-1: link qh0-00ff/df91b100 start 0 [1/0 us]
[  143.417865] drivers/usb/serial/magtek.c: magtek_startup - usb_submit_urb(int urb)
[  143.418108] usb 1-1: Magtek 75/Excella USB card reader converter now attached to ttyUSB0
[  143.418874] drivers/usb/core/inode.c: creating file '004'
[  143.419046] usb 1-1: New USB device found, idVendor=0801, idProduct=2231
[  143.419052] usb 1-1: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[  143.419056] usb 1-1: Product: STX
[  143.419059] usb 1-1: Manufacturer: MagTek
[  143.419062] usb 1-1: SerialNumber: STX001
[  148.765273] hub 1-0:1.0: state 7 ports 6 chg 0000 evt 0004
[  148.765273] ehci_hcd 0000:00:1d.7: GetStatus port 2 status 001803 POWER sig=j CSC CONNECT
[  148.765273] hub 1-0:1.0: port 2, status 0501, change 0001, 480 Mb/s
[  148.892021] hub 1-0:1.0: debounce: port 2: total 100ms stable 100ms status 0x501
[  148.948172] ehci_hcd 0000:00:1d.7: port 2 full speed --> companion
[  148.948184] ehci_hcd 0000:00:1d.7: GetStatus port 2 status 003801 POWER OWNER sig=j CONNECT
[  148.948201] usb usb2: wakeup_rh (auto-start)
[  148.948222] hub 1-0:1.0: port 2 not reset yet, waiting 50ms
[  149.004019] ehci_hcd 0000:00:1d.7: GetStatus port 2 status 003002 POWER OWNER sig=se0 CSC
[  149.004054] hub 2-0:1.0: state 7 ports 2 chg 0000 evt 0004
[  149.004065] uhci_hcd 0000:00:1d.0: port 2 portsc 0093,00
[  149.004075] hub 2-0:1.0: port 2, status 0101, change 0001, 12 Mb/s
[  149.132021] hub 2-0:1.0: debounce: port 2: total 100ms stable 100ms status 0x101
[  149.244042] usb 2-2: new full speed USB device using uhci_hcd and address 2
[  149.376015] usb 2-2: ep0 maxpacket = 8
[  149.399097] usb 2-2: default language 0x0409
[  149.408004] usb 2-2: uevent
[  149.418007] usb 2-2: usb_probe_device
[  149.418019] usb 2-2: configuration #1 chosen from 1 choice
[  149.421042] usb 2-2: adding 2-2:1.0 (config #1, interface 0)
[  149.421112] usb 2-2:1.0: uevent
[  149.421158] usbserial_generic 2-2:1.0: usb_probe_interface
[  149.421163] usbserial_generic 2-2:1.0: usb_probe_interface - got id
[  149.421182] magtek 2-2:1.0: usb_probe_interface
[  149.421186] magtek 2-2:1.0: usb_probe_interface - got id
[  149.421193] magtek 2-2:1.0: Magtek 75/Excella USB card reader converter detected
[  149.421201] drivers/usb/serial/magtek.c: magtek_startup
[  149.421219] uhci_hcd 0000:00:1d.0: reserve dev 2 ep81-INT, period 8, phase 4, 61 us
[  149.421224] drivers/usb/serial/magtek.c: magtek_startup - usb_submit_urb(int urb)
[  149.421453] usb 2-2: Magtek 75/Excella USB card reader converter now attached to ttyUSB1
[  149.421595] drivers/usb/core/inode.c: creating file '002'
[  149.421662] usb 2-2: New USB device found, idVendor=0801, idProduct=000a
[  149.421668] usb 2-2: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[  149.421672] usb 2-2: Product: IntelliStripe 65
[  149.421675] usb 2-2: Manufacturer: MagTek
[  149.421683] hub 1-0:1.0: state 7 ports 6 chg 0000 evt 0004
[  167.564004] hub 1-0:1.0: state 7 ports 6 chg 0000 evt 0002
[  167.564004] ehci_hcd 0000:00:1d.7: GetStatus port 1 status 001002 POWER sig=se0 CSC
[  167.564004] hub 1-0:1.0: port 1, status 0100, change 0001, 12 Mb/s
[  167.564004] usb 1-1: USB disconnect, address 4
[  167.564004] usb 1-1: unregistering device
[  167.564004] usb 1-1: usb_disable_device nuking all URBs
[  167.564004] usb 1-1: unlink qh0-00ff/df91b100 start 0 [1/0 us]
[  167.564004] drivers/usb/serial/magtek.c: magtek_read_int_callback - port 0
[  167.564004] ehci_hcd 0000:00:1d.7: shutdown urb df794600 ep2in-intr
[  167.564004] usb 1-1: unregistering interface 1-1:1.0
[  167.564004] drivers/usb/serial/magtek.c: magtek_shutdown
[  167.571167] magtek ttyUSB0: Magtek 75/Excella USB card reader converter now disconnected from ttyUSB0
[  167.571226] magtek 1-1:1.0: device disconnected
[  167.571241] usb 1-1:1.0: uevent
[  167.571640] usb 1-1: uevent
[  167.696020] hub 1-0:1.0: debounce: port 1: total 100ms stable 100ms status 0x100
[  170.949363] usb 2-2: uhci_result_common: failed with status 440000
[  170.949363] drivers/usb/serial/magtek.c: magtek_read_int_callback - port 1
[  170.949363] uhci_hcd 0000:00:1d.0: release dev 2 ep81-INT, period 8, phase 4, 61 us
[  171.024049] hub 2-0:1.0: state 7 ports 2 chg 0000 evt 0004
[  171.024068] uhci_hcd 0000:00:1d.0: port 2 portsc 008a,00
[  171.024083] hub 2-0:1.0: port 2, status 0100, change 0003, 12 Mb/s
[  171.024089] usb 2-2: USB disconnect, address 2
[  171.024092] usb 2-2: unregistering device
[  171.024096] usb 2-2: usb_disable_device nuking all URBs
[  171.024105] usb 2-2: unregistering interface 2-2:1.0
[  171.024196] drivers/usb/serial/magtek.c: magtek_shutdown
[  171.028630] magtek ttyUSB1: Magtek 75/Excella USB card reader converter now disconnected from ttyUSB1
[  171.028695] magtek 2-2:1.0: device disconnected
[  171.028710] usb 2-2:1.0: uevent
[  171.029093] usb 2-2: uevent
[  171.156020] hub 2-0:1.0: debounce: port 2: total 100ms stable 100ms status 0x100
[  172.512024] usb usb2: suspend_rh (auto-stop)
[  175.874728] hub 1-0:1.0: state 7 ports 6 chg 0000 evt 0004
[  175.874728] ehci_hcd 0000:00:1d.7: GetStatus port 2 status 001803 POWER sig=j CSC CONNECT
[  175.874728] hub 1-0:1.0: port 2, status 0501, change 0001, 480 Mb/s
[  176.004020] hub 1-0:1.0: debounce: port 2: total 100ms stable 100ms status 0x501
[  176.060196] ehci_hcd 0000:00:1d.7: port 2 full speed --> companion
[  176.060207] ehci_hcd 0000:00:1d.7: GetStatus port 2 status 003801 POWER OWNER sig=j CONNECT
[  176.060222] usb usb2: wakeup_rh (auto-start)
[  176.060235] hub 1-0:1.0: port 2 not reset yet, waiting 50ms
[  176.116022] ehci_hcd 0000:00:1d.7: GetStatus port 2 status 003002 POWER OWNER sig=se0 CSC
[  176.116057] hub 2-0:1.0: state 7 ports 2 chg 0000 evt 0004
[  176.116068] uhci_hcd 0000:00:1d.0: port 2 portsc 0093,00
[  176.116078] hub 2-0:1.0: port 2, status 0101, change 0001, 12 Mb/s
[  176.244020] hub 2-0:1.0: debounce: port 2: total 100ms stable 100ms status 0x101
[  176.356016] usb 2-2: new full speed USB device using uhci_hcd and address 3
[  176.488015] usb 2-2: ep0 maxpacket = 8
[  176.500004] usb 2-2: default language 0x0409
[  176.504004] usb 2-2: uevent
[  176.529878] usb 2-2: usb_probe_device
[  176.529887] usb 2-2: configuration #1 chosen from 1 choice
[  176.533029] usb 2-2: adding 2-2:1.0 (config #1, interface 0)
[  176.533102] usb 2-2:1.0: uevent
[  176.533148] usbserial_generic 2-2:1.0: usb_probe_interface
[  176.533153] usbserial_generic 2-2:1.0: usb_probe_interface - got id
[  176.533172] magtek 2-2:1.0: usb_probe_interface
[  176.533176] magtek 2-2:1.0: usb_probe_interface - got id
[  176.533183] magtek 2-2:1.0: Magtek 75/Excella USB card reader converter detected
[  176.533192] drivers/usb/serial/magtek.c: magtek_startup
[  176.533211] uhci_hcd 0000:00:1d.0: reserve dev 3 ep81-INT, period 8, phase 4, 61 us
[  176.533217] drivers/usb/serial/magtek.c: magtek_startup - usb_submit_urb(int urb)
[  176.533438] usb 2-2: Magtek 75/Excella USB card reader converter now attached to ttyUSB0
[  176.533595] drivers/usb/core/inode.c: creating file '003'
[  176.533663] usb 2-2: New USB device found, idVendor=0801, idProduct=000a
[  176.533668] usb 2-2: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[  176.533672] usb 2-2: Product: IntelliStripe 65
[  176.533675] usb 2-2: Manufacturer: MagTek
[  176.533684] hub 1-0:1.0: state 7 ports 6 chg 0000 evt 0004
[  182.697945] hub 1-0:1.0: state 7 ports 6 chg 0000 evt 0002
[  182.697966] ehci_hcd 0000:00:1d.7: GetStatus port 1 status 001803 POWER sig=j CSC CONNECT
[  182.697980] hub 1-0:1.0: port 1, status 0501, change 0001, 480 Mb/s
[  182.824020] hub 1-0:1.0: debounce: port 1: total 100ms stable 100ms status 0x501
[  182.880323] ehci_hcd 0000:00:1d.7: port 1 high speed
[  182.880333] ehci_hcd 0000:00:1d.7: GetStatus port 1 status 001005 POWER sig=se0 PE CONNECT
[  182.936025] usb 1-1: new high speed USB device using ehci_hcd and address 7
[  182.992298] ehci_hcd 0000:00:1d.7: port 1 high speed
[  182.992312] ehci_hcd 0000:00:1d.7: GetStatus port 1 status 001005 POWER sig=se0 PE CONNECT
[  183.068539] usb 1-1: default language 0x0409
[  183.068999] usb 1-1: uevent
[  183.073134] usb 1-1: usb_probe_device
[  183.073148] usb 1-1: configuration #1 chosen from 1 choice
[  183.073452] usb 1-1: adding 1-1:1.0 (config #1, interface 0)
[  183.073511] usb 1-1:1.0: uevent
[  183.073580] usbserial_generic 1-1:1.0: usb_probe_interface
[  183.073585] usbserial_generic 1-1:1.0: usb_probe_interface - got id
[  183.073605] magtek 1-1:1.0: usb_probe_interface
[  183.073609] magtek 1-1:1.0: usb_probe_interface - got id
[  183.073617] magtek 1-1:1.0: Magtek 75/Excella USB card reader converter detected
[  183.073624] drivers/usb/serial/magtek.c: magtek_startup
[  183.073752] usb 1-1: link qh0-00ff/df91b080 start 0 [1/0 us]
[  183.076223] magtek:  usb_submit_urb(read int) failed
[  183.076231] drivers/usb/serial/magtek.c: magtek_startup - usb_submit_urb(int urb)
[  183.076461] usb 1-1: Magtek 75/Excella USB card reader converter now attached to ttyUSB1
[  183.076599] drivers/usb/core/inode.c: creating file '007'
[  183.076669] usb 1-1: New USB device found, idVendor=0801, idProduct=2231
[  183.076674] usb 1-1: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[  183.076678] usb 1-1: Product: STX
[  183.076681] usb 1-1: Manufacturer: MagTek
[  183.076684] usb 1-1: SerialNumber: STX001
[  185.704529] irq 23: nobody cared (try booting with the "irqpoll" option)
[  185.704529] Pid: 3505, comm: automount Not tainted 2.6.26-KGDB #1
[  185.704529]  [<c013fe84>] __report_bad_irq+0x2e/0x6f
[  185.704529]  [<c0140098>] note_interrupt+0x1d3/0x207
[  185.704529]  [<c013f60e>] ? handle_IRQ_event+0x21/0x48
[  185.704529]  [<c01407c0>] handle_fasteoi_irq+0x8a/0xaa
[  185.704529]  [<c01056f2>] do_IRQ+0x71/0x8b
[  185.704529]  [<c010416b>] common_interrupt+0x23/0x28
[  185.704529]  [<c012007b>] ? prof_cpu_mask_write_proc+0xf/0x2f
[  185.704529]  [<c0103747>] ? sysenter_past_esp+0x38/0x91
[  185.704529]  =======================
[  185.704529] handlers:
[  185.704529] [<c03428d9>] (usb_hcd_irq+0x0/0x58)


Thanks
Amruth p.v


--- On Thu, 8/21/08, amruth <amruth_pv@yahoo.com> wrote:

> From: amruth <amruth_pv@yahoo.com>
> Subject: USB Serial device disconnect causes IRQ disable details captured
> To: "Alan Stern" <stern@rowland.harvard.edu>
> Cc: "Oliver Neukum" <oliver@neukum.org>, linux-usb@vger.kernel.org, linux-kernel@vger.kernel.org
> Date: Thursday, August 21, 2008, 4:52 PM
> Thanks Alan. I will test in another computers with the new
> patch and let you know if I again find the issue.
> 
> Thanks
> Amruth p.v
> 
> 
> --- On Thu, 8/21/08, Alan Stern
> <stern@rowland.harvard.edu> wrote:
> 
> > From: Alan Stern <stern@rowland.harvard.edu>
> > Subject: Re: USB Serial device disconnect causes IRQ
> disable details captured
> > To: "amruth" <amruth_pv@yahoo.com>
> > Cc: "Oliver Neukum"
> <oliver@neukum.org>, linux-usb@vger.kernel.org,
> linux-kernel@vger.kernel.org
> > Date: Thursday, August 21, 2008, 4:20 PM
> > On Thu, 21 Aug 2008, amruth wrote:
> > 
> > > Hi
> > > Oliver
> > > I got the same issue once again. I have captured
> > detail log and lusb -t with interrupts.
> > > cat /proc/interrupts:
> > 
> > > dmesg:
> > > sb 1-5: Magtek 75/Excella USB card reader
> converter
> > now attached to ttyUSB1
> > > drivers/usb/core/inode.c: creating file
> '012'
> > > usb 1-5: New USB device found, idVendor=0801,
> > idProduct=2231
> > > usb 1-5: New USB device strings: Mfr=1,
> Product=2,
> > SerialNumber=3
> > > usb 1-5: Product: STX
> > > usb 1-5: Manufacturer: MagTek
> > > usb 1-5: SerialNumber: STX001
> > > usb 2-2: uhci_result_common: failed with status
> 440000
> > >
> /home/amr/linux-2.6.26/drivers/usb/serial/magtek.c:
> > magtek_read_int_callback - p
> > > ort 0
> > > uhci_hcd 0000:00:1d.0: release dev 6 ep81-INT,
> period
> > 8, phase 4, 61 us
> > > hub 2-0:1.0: state 7 ports 2 chg 0000 evt 0004
> > > uhci_hcd 0000:00:1d.0: port 2 portsc 008a,00
> > > hub 2-0:1.0: port 2, status 0100, change 0003, 12
> Mb/s
> > > usb 2-2: USB disconnect, address 6
> > > usb 2-2: unregistering device
> > > usb 2-2: usb_disable_device nuking all URBs
> > > usb 2-2: unregistering interface 2-2:1.0
> > >
> /home/amr/linux-2.6.26/drivers/usb/serial/magtek.c:
> > magtek_shutdown
> > > magtek ttyUSB0: Magtek 75/Excella USB card reader
> > converter now disconnected from ttyUSB0
> > > magtek 2-2:1.0: device disconnected
> > > usb 2-2:1.0: uevent
> > > usb 2-2: uevent
> > > hub 2-0:1.0: debounce: port 2: total 100ms stable
> > 100ms status 0x100
> > > usb usb2: suspend_rh (auto-stop)
> > > ehci_hcd 0000:00:1d.7: devpath 5 ep2in 3strikes
> > >
> /home/amr/linux-2.6.26/drivers/usb/serial/magtek.c:
> > magtek_read_int_callback - port 1
> > > usb 1-5: unlink qh0-00ff/dec56380 start 0 [1/0
> us]
> > > usb 1-5: link qh0-00ff/dec56380 start 0 [1/0 us]
> > > usb 1-5: unlink qh0-00ff/dec56380 start 0 [1/0
> us]
> > > ehci_hcd 0000:00:1d.7: HC died; cleaning up
> > 
> > You should try using the patch in this message:
> > 
> >
> 	http://marc.info/?l=linux-usb&m=121848784300960&w=2
> > 
> > If that doesn't help, can you test this on another
> > computer to see if
> > the same thing happens?
> > 
> > For future testing, it would help if you enable
> > CONFIG_PRINTK_TIME.
> > 
> > Alan Stern
> 
> 
>       
> 
> --
> To unsubscribe from this list: send the line
> "unsubscribe linux-usb" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at 
> http://vger.kernel.org/majordomo-info.html


      

Re: USB Serial device disconnect causes IRQ disable not working after patch

[Alan Stern]

On Mon, 25 Aug 2008, amruth wrote:

> Hi
> Alan
> The patch suggested by you did not work. I tried in another computer and found same issue. I have detailed log below.

This log shows you have 2 Magtek devices: one running at high speed and 
one running at full speed:

> [  143.041808] hub 1-0:1.0: state 7 ports 6 chg 0000 evt 0002
> [  143.041808] ehci_hcd 0000:00:1d.7: GetStatus port 1 status 001803 POWER sig=j CSC CONNECT
> [  143.041808] hub 1-0:1.0: port 1, status 0501, change 0001, 480 Mb/s
> [  143.168024] hub 1-0:1.0: debounce: port 1: total 100ms stable 100ms status 0x501
> [  143.224309] ehci_hcd 0000:00:1d.7: port 1 high speed
> [  143.224323] ehci_hcd 0000:00:1d.7: GetStatus port 1 status 001005 POWER sig=se0 PE CONNECT
> [  143.280021] usb 1-1: new high speed USB device using ehci_hcd and address 4
> [  143.336281] ehci_hcd 0000:00:1d.7: port 1 high speed
> [  143.336292] ehci_hcd 0000:00:1d.7: GetStatus port 1 status 001005 POWER sig=se0 PE CONNECT
> [  143.412650] usb 1-1: default language 0x0409
> [  143.413121] usb 1-1: uevent
> [  143.417056] usb 1-1: usb_probe_device
> [  143.417068] usb 1-1: configuration #1 chosen from 1 choice
> [  143.417361] usb 1-1: adding 1-1:1.0 (config #1, interface 0)
> [  143.417422] usb 1-1:1.0: uevent
> [  143.417622] usbserial_generic 1-1:1.0: usb_probe_interface
> [  143.417627] usbserial_generic 1-1:1.0: usb_probe_interface - got id
> [  143.417646] magtek 1-1:1.0: usb_probe_interface
> [  143.417650] magtek 1-1:1.0: usb_probe_interface - got id
> [  143.417659] magtek 1-1:1.0: Magtek 75/Excella USB card reader converter detected

That was the high-speed device.

> [  148.765273] hub 1-0:1.0: state 7 ports 6 chg 0000 evt 0004
> [  148.765273] ehci_hcd 0000:00:1d.7: GetStatus port 2 status 001803 POWER sig=j CSC CONNECT
> [  148.765273] hub 1-0:1.0: port 2, status 0501, change 0001, 480 Mb/s
> [  148.892021] hub 1-0:1.0: debounce: port 2: total 100ms stable 100ms status 0x501
> [  148.948172] ehci_hcd 0000:00:1d.7: port 2 full speed --> companion
> [  148.948184] ehci_hcd 0000:00:1d.7: GetStatus port 2 status 003801 POWER OWNER sig=j CONNECT
> [  148.948201] usb usb2: wakeup_rh (auto-start)
> [  148.948222] hub 1-0:1.0: port 2 not reset yet, waiting 50ms
> [  149.004019] ehci_hcd 0000:00:1d.7: GetStatus port 2 status 003002 POWER OWNER sig=se0 CSC
> [  149.004054] hub 2-0:1.0: state 7 ports 2 chg 0000 evt 0004
> [  149.004065] uhci_hcd 0000:00:1d.0: port 2 portsc 0093,00
> [  149.004075] hub 2-0:1.0: port 2, status 0101, change 0001, 12 Mb/s
> [  149.132021] hub 2-0:1.0: debounce: port 2: total 100ms stable 100ms status 0x101
> [  149.244042] usb 2-2: new full speed USB device using uhci_hcd and address 2
> [  149.376015] usb 2-2: ep0 maxpacket = 8
> [  149.399097] usb 2-2: default language 0x0409
> [  149.408004] usb 2-2: uevent
> [  149.418007] usb 2-2: usb_probe_device
> [  149.418019] usb 2-2: configuration #1 chosen from 1 choice
> [  149.421042] usb 2-2: adding 2-2:1.0 (config #1, interface 0)
> [  149.421112] usb 2-2:1.0: uevent
> [  149.421158] usbserial_generic 2-2:1.0: usb_probe_interface
> [  149.421163] usbserial_generic 2-2:1.0: usb_probe_interface - got id
> [  149.421182] magtek 2-2:1.0: usb_probe_interface
> [  149.421186] magtek 2-2:1.0: usb_probe_interface - got id
> [  149.421193] magtek 2-2:1.0: Magtek 75/Excella USB card reader converter detected

That was the full-speed device.  Does it make any difference if you use 
only one of them instead of both?

> [  185.704529] irq 23: nobody cared (try booting with the "irqpoll" option)
> [  185.704529] Pid: 3505, comm: automount Not tainted 2.6.26-KGDB #1
> [  185.704529]  [<c013fe84>] __report_bad_irq+0x2e/0x6f
> [  185.704529]  [<c0140098>] note_interrupt+0x1d3/0x207
> [  185.704529]  [<c013f60e>] ? handle_IRQ_event+0x21/0x48
> [  185.704529]  [<c01407c0>] handle_fasteoi_irq+0x8a/0xaa
> [  185.704529]  [<c01056f2>] do_IRQ+0x71/0x8b
> [  185.704529]  [<c010416b>] common_interrupt+0x23/0x28
> [  185.704529]  [<c012007b>] ? prof_cpu_mask_write_proc+0xf/0x2f
> [  185.704529]  [<c0103747>] ? sysenter_past_esp+0x38/0x91
> [  185.704529]  =======================
> [  185.704529] handlers:
> [  185.704529] [<c03428d9>] (usb_hcd_irq+0x0/0x58)

Try adding a statement saying:

	ehci_info(ehci, "irq status %x masked %x\n", status,
			status & INTR_MASK);

to ehci-hcd.c inside ehci_irq(), just before the line that does

	status &= INTR_MASK;

Then let's see what happens.

Alan Stern

USB Serial device disconnect causes IRQ disable after using ehci_info

[amruth]

Hi
Alan

> That was the full-speed device.  Does it make any
> difference if you use 
> only one of them instead of both?
> 
The problem is seen when both are used.

> Try adding a statement saying:
> 
>ehci_info(ehci, "irq status %x masked %x\n",
> status,
>status & INTR_MASK);
>> to ehci-hcd.c inside ehci_irq(), just before the line that
> does 	status &= INTR_MASK;
> 
> Then let's see what happens.
Here is the output after using ehci_info

[  310.517577] usbcore: registered new interface driver usbserial
[  310.519417] usbserial: USB Serial support registered for generic
[  310.521129] usbcore: registered new interface driver usbserial_generic
[  310.521141] usbserial: USB Serial Driver core
[  310.600476] usbserial: USB Serial support registered for TI USB 3410 1 port adapter
[  310.602481] usbserial: USB Serial support registered for TI USB 5052 2 port adapter
[  310.602481] usbcore: registered new interface driver ti_usb_3410_5052
[  310.602481] ti_usb_3410_5052: TI USB 3410/5052 Serial Driver v0.9
[  416.344945] ehci_hcd 0000:00:1d.7: irq status c masked 4
[  416.344982] hub 5-0:1.0: state 7 ports 8 chg 0000 evt 0020
[  416.344994] ehci_hcd 0000:00:1d.7: GetStatus port 5 status 001803 POWER sig=j CSC CONNECT
[  416.345005] hub 5-0:1.0: port 5, status 0501, change 0001, 480 Mb/s
[  416.448335] hub 5-0:1.0: debounce: port 5: total 100ms stable 100ms status 0x501
[  416.499523] ehci_hcd 0000:00:1d.7: port 5 full speed --> companion
[  416.499533] ehci_hcd 0000:00:1d.7: GetStatus port 5 status 003801 POWER OWNER sig=j CONNECT
[  416.499547] usb usb3: wakeup_rh (auto-start)
[  416.499565] hub 5-0:1.0: port 5 not reset yet, waiting 50ms
[  416.503458] ehci_hcd 0000:00:1d.7: irq status c masked 4
[  416.550314] ehci_hcd 0000:00:1d.7: GetStatus port 5 status 003002 POWER OWNER sig=se0 CSC
[  416.550353] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0002
[  416.550366] uhci_hcd 0000:00:1d.2: port 1 portsc 0093,00
[  416.550379] hub 3-0:1.0: port 1, status 0101, change 0001, 12 Mb/s
[  416.654286] hub 3-0:1.0: debounce: port 1: total 100ms stable 100ms status 0x101
[  416.756259] usb 3-1: new full speed USB device using uhci_hcd and address 2
[  416.876237] usb 3-1: ep0 maxpacket = 8
[  416.899501] usb 3-1: default language 0x0409
[  416.914558] usb 3-1: uevent
[  416.914605] usb 3-1: usb_probe_device
[  416.914612] usb 3-1: configuration #1 chosen from 1 choice
[  416.917621] usb 3-1: adding 3-1:1.0 (config #1, interface 0)
[  416.917683] usb 3-1:1.0: uevent
[  416.917944] usbserial_generic 3-1:1.0: usb_probe_interface
[  416.917950] usbserial_generic 3-1:1.0: usb_probe_interface - got id
[  416.920536] drivers/usb/core/inode.c: creating file '002'
[  416.920736] usb 3-1: New USB device found, idVendor=0801, idProduct=000a
[  416.920742] usb 3-1: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[  416.920749] usb 3-1: Product: IntelliStripe 65
[  416.920753] usb 3-1: Manufacturer: MagTek
[  416.920762] hub 5-0:1.0: state 7 ports 8 chg 0000 evt 0020
[  417.604928] usbserial: USB Serial support registered for Magtek 75/Excella USB card reader
[  417.606929] magtek 3-1:1.0: usb_probe_interface
[  417.606929] magtek 3-1:1.0: usb_probe_interface - got id
[  417.606929] magtek 3-1:1.0: Magtek 75/Excella USB card reader converter detected
[  417.606929] drivers/usb/serial/magtek.c: magtek_startup
[  417.606929] uhci_hcd 0000:00:1d.2: reserve dev 2 ep81-INT, period 8, phase 4, 61 us
[  417.606929] drivers/usb/serial/magtek.c: magtek_startup - usb_submit_urb(int urb)
[  417.606929] usb 3-1: Magtek 75/Excella USB card reader converter now attached to ttyUSB0
[  417.607927] usbcore: registered new interface driver magtek
[  417.607927] magtek: v1.01 Amruth Vamadev
[  417.607927] magtek: MAGTEK 75/Excella check USB Chipcard Reader Driver
[  469.065999] ehci_hcd 0000:00:1d.7: irq status c masked 4
[  469.066035] hub 5-0:1.0: state 7 ports 8 chg 0000 evt 0004
[  469.066045] ehci_hcd 0000:00:1d.7: GetStatus port 2 status 001803 POWER sig=j CSC CONNECT
[  469.066056] hub 5-0:1.0: port 2, status 0501, change 0001, 480 Mb/s
[  469.169441] hub 5-0:1.0: debounce: port 2: total 100ms stable 100ms status 0x501
[  469.220697] ehci_hcd 0000:00:1d.7: port 2 high speed
[  469.220708] ehci_hcd 0000:00:1d.7: GetStatus port 2 status 001005 POWER sig=se0 PE CONNECT
[  469.271415] usb 5-2: new high speed USB device using ehci_hcd and address 4
[  469.272398] ehci_hcd 0000:00:1d.7: irq status 8009 masked 1
[  469.276912] ehci_hcd 0000:00:1d.7: irq status 8028 masked 20
[  469.323607] ehci_hcd 0000:00:1d.7: port 2 high speed
[  469.323617] ehci_hcd 0000:00:1d.7: GetStatus port 2 status 001005 POWER sig=se0 PE CONNECT
[  469.374478] ehci_hcd 0000:00:1d.7: irq status 8009 masked 1
[  469.374601] ehci_hcd 0000:00:1d.7: irq status 8028 masked 20
[  469.387239] ehci_hcd 0000:00:1d.7: irq status 8009 masked 1
[  469.387365] ehci_hcd 0000:00:1d.7: irq status 8009 masked 1
[  469.387414] ehci_hcd 0000:00:1d.7: irq status 8009 masked 1
[  469.387460] ehci_hcd 0000:00:1d.7: irq status 8009 masked 1
[  469.387513] usb 5-2: default language 0x0409
[  469.387710] ehci_hcd 0000:00:1d.7: irq status 8009 masked 1
[  469.387836] ehci_hcd 0000:00:1d.7: irq status 8009 masked 1
[  469.387960] ehci_hcd 0000:00:1d.7: irq status 8009 masked 1
[  469.388033] usb 5-2: uevent
[  469.388101] usb 5-2: usb_probe_device
[  469.388108] usb 5-2: configuration #1 chosen from 1 choice
[  469.388211] ehci_hcd 0000:00:1d.7: irq status 8009 masked 1
[  469.388336] usb 5-2: adding 5-2:1.0 (config #1, interface 0)
[  469.388385] usb 5-2:1.0: uevent
[  469.388429] usbserial_generic 5-2:1.0: usb_probe_interface
[  469.388435] usbserial_generic 5-2:1.0: usb_probe_interface - got id
[  469.388454] magtek 5-2:1.0: usb_probe_interface
[  469.388458] magtek 5-2:1.0: usb_probe_interface - got id
[  469.388496] magtek 5-2:1.0: Magtek 75/Excella USB card reader converter detected
[  469.388508] drivers/usb/serial/magtek.c: magtek_startup
[  469.388663] usb 5-2: link qh0-00ff/ded71100 start 0 [1/0 us]
[  469.388719] drivers/usb/serial/magtek.c: magtek_startup - usb_submit_urb(int urb)
[  469.388835] usb 5-2: Magtek 75/Excella USB card reader converter now attached to ttyUSB1
[  469.389651] drivers/usb/core/inode.c: creating file '004'
[  469.389759] usb 5-2: New USB device found, idVendor=0801, idProduct=2231
[  469.389766] usb 5-2: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[  469.389772] usb 5-2: Product: STX
[  469.389777] usb 5-2: Manufacturer: MagTek
[  469.389781] usb 5-2: SerialNumber: STX001
[  469.393023] ehci_hcd 0000:00:1d.7: irq status c028 masked 20
[  507.575453] ehci_hcd 0000:00:1d.7: irq status 600b masked 3
[  507.575465] ehci_hcd 0000:00:1d.7: devpath 2 ep2in 3strikes
[  507.575470] drivers/usb/serial/magtek.c: magtek_read_int_callback - port 1
[  507.575484] usb 5-2: unlink qh0-00ff/ded71100 start 0 [1/0 us]
[  507.576084] usb 5-2: link qh0-00ff/ded71100 start 0 [1/0 us]
[  507.576548] usb 5-2: unlink qh0-00ff/ded71100 start 0 [1/0 us]
[  507.576548] ehci_hcd 0000:00:1d.7: HC died; cleaning up
[  507.579131] hub 5-0:1.0: state 0 ports 8 chg 0000 evt 0000
[  507.579137] usb 5-2: USB disconnect, address 4
[  507.579141] usb 5-2: unregistering device
[  507.579145] usb 5-2: usb_disable_device nuking all URBs
[  507.579155] usb 5-2: unregistering interface 5-2:1.0
[  507.579261] drivers/usb/serial/magtek.c: magtek_shutdown
[  507.579418] magtek ttyUSB1: Magtek 75/Excella USB card reader converter now disconnected from ttyUSB1
[  507.579450] magtek 5-2:1.0: device disconnected
[  507.579464] usb 5-2:1.0: uevent
[  507.581083] usb 5-2: uevent
[  507.877032] irq 23: nobody cared (try booting with the "irqpoll" option)
[  507.877042] Pid: 0, comm: swapper Not tainted 2.6.26patched #2
[  507.877063]  [<c044c0cc>] __report_bad_irq+0x2e/0x6f
[  507.877078]  [<c044c2e4>] note_interrupt+0x1d7/0x20b
[  507.877089]  [<c044b852>] ? handle_IRQ_event+0x21/0x48
[  507.877103]  [<c044ca0f>] handle_fasteoi_irq+0x8b/0xac
[  507.877114]  [<c044c984>] ? handle_fasteoi_irq+0x0/0xac
[  507.877123]  [<c040598c>] do_IRQ+0xa9/0xd1
[  507.877131]  [<c04025f2>] ? default_idle+0x0/0x42
[  507.877142]  [<c040429b>] common_interrupt+0x23/0x28
[  507.877148]  [<c04025f2>] ? default_idle+0x0/0x42
[  507.877167]  [<c040261f>] ? default_idle+0x2d/0x42
[  507.877178]  [<c040256d>] cpu_idle+0x8b/0x9f
[  507.877187]  [<c0610d62>] rest_init+0x4e/0x50
[  507.877204]  =======================
[  507.877207] handlers:
[  507.877209] [<c057649d>] (usb_hcd_irq+0x0/0x58)
[  507.877217] Disabling IRQ #23


Thanks
Amruth p.v


--- On Mon, 8/25/08, Alan Stern <stern@rowland.harvard.edu> wrote:

> From: Alan Stern <stern@rowland.harvard.edu>
> Subject: Re: USB Serial device disconnect causes IRQ disable not working after patch
> To: "amruth" <amruth_pv@yahoo.com>
> Cc: "Oliver Neukum" <oliver@neukum.org>, linux-usb@vger.kernel.org, linux-kernel@vger.kernel.org
> Date: Monday, August 25, 2008, 1:50 PM
> On Mon, 25 Aug 2008, amruth wrote:
> 
> > Hi
> > Alan
> > The patch suggested by you did not work. I tried in
> another computer and found same issue. I have detailed log
> below.
> 
> This log shows you have 2 Magtek devices: one running at
> high speed and 
> one running at full speed:
> 
> > [  143.041808] hub 1-0:1.0: state 7 ports 6 chg 0000
> evt 0002
> > [  143.041808] ehci_hcd 0000:00:1d.7: GetStatus port 1
> status 001803 POWER sig=j CSC CONNECT
> > [  143.041808] hub 1-0:1.0: port 1, status 0501,
> change 0001, 480 Mb/s
> > [  143.168024] hub 1-0:1.0: debounce: port 1: total
> 100ms stable 100ms status 0x501
> > [  143.224309] ehci_hcd 0000:00:1d.7: port 1 high
> speed
> > [  143.224323] ehci_hcd 0000:00:1d.7: GetStatus port 1
> status 001005 POWER sig=se0 PE CONNECT
> > [  143.280021] usb 1-1: new high speed USB device
> using ehci_hcd and address 4
> > [  143.336281] ehci_hcd 0000:00:1d.7: port 1 high
> speed
> > [  143.336292] ehci_hcd 0000:00:1d.7: GetStatus port 1
> status 001005 POWER sig=se0 PE CONNECT
> > [  143.412650] usb 1-1: default language 0x0409
> > [  143.413121] usb 1-1: uevent
> > [  143.417056] usb 1-1: usb_probe_device
> > [  143.417068] usb 1-1: configuration #1 chosen from 1
> choice
> > [  143.417361] usb 1-1: adding 1-1:1.0 (config #1,
> interface 0)
> > [  143.417422] usb 1-1:1.0: uevent
> > [  143.417622] usbserial_generic 1-1:1.0:
> usb_probe_interface
> > [  143.417627] usbserial_generic 1-1:1.0:
> usb_probe_interface - got id
> > [  143.417646] magtek 1-1:1.0: usb_probe_interface
> > [  143.417650] magtek 1-1:1.0: usb_probe_interface -
> got id
> > [  143.417659] magtek 1-1:1.0: Magtek 75/Excella USB
> card reader converter detected
> 
> That was the high-speed device.
> 
> > [  148.765273] hub 1-0:1.0: state 7 ports 6 chg 0000
> evt 0004
> > [  148.765273] ehci_hcd 0000:00:1d.7: GetStatus port 2
> status 001803 POWER sig=j CSC CONNECT
> > [  148.765273] hub 1-0:1.0: port 2, status 0501,
> change 0001, 480 Mb/s
> > [  148.892021] hub 1-0:1.0: debounce: port 2: total
> 100ms stable 100ms status 0x501
> > [  148.948172] ehci_hcd 0000:00:1d.7: port 2 full
> speed --> companion
> > [  148.948184] ehci_hcd 0000:00:1d.7: GetStatus port 2
> status 003801 POWER OWNER sig=j CONNECT
> > [  148.948201] usb usb2: wakeup_rh (auto-start)
> > [  148.948222] hub 1-0:1.0: port 2 not reset yet,
> waiting 50ms
> > [  149.004019] ehci_hcd 0000:00:1d.7: GetStatus port 2
> status 003002 POWER OWNER sig=se0 CSC
> > [  149.004054] hub 2-0:1.0: state 7 ports 2 chg 0000
> evt 0004
> > [  149.004065] uhci_hcd 0000:00:1d.0: port 2 portsc
> 0093,00
> > [  149.004075] hub 2-0:1.0: port 2, status 0101,
> change 0001, 12 Mb/s
> > [  149.132021] hub 2-0:1.0: debounce: port 2: total
> 100ms stable 100ms status 0x101
> > [  149.244042] usb 2-2: new full speed USB device
> using uhci_hcd and address 2
> > [  149.376015] usb 2-2: ep0 maxpacket = 8
> > [  149.399097] usb 2-2: default language 0x0409
> > [  149.408004] usb 2-2: uevent
> > [  149.418007] usb 2-2: usb_probe_device
> > [  149.418019] usb 2-2: configuration #1 chosen from 1
> choice
> > [  149.421042] usb 2-2: adding 2-2:1.0 (config #1,
> interface 0)
> > [  149.421112] usb 2-2:1.0: uevent
> > [  149.421158] usbserial_generic 2-2:1.0:
> usb_probe_interface
> > [  149.421163] usbserial_generic 2-2:1.0:
> usb_probe_interface - got id
> > [  149.421182] magtek 2-2:1.0: usb_probe_interface
> > [  149.421186] magtek 2-2:1.0: usb_probe_interface -
> got id
> > [  149.421193] magtek 2-2:1.0: Magtek 75/Excella USB
> card reader converter detected
> 
> That was the full-speed device.  Does it make any
> difference if you use 
> only one of them instead of both?
> 
> > [  185.704529] irq 23: nobody cared (try booting with
> the "irqpoll" option)
> > [  185.704529] Pid: 3505, comm: automount Not tainted
> 2.6.26-KGDB #1
> > [  185.704529]  [<c013fe84>]
> __report_bad_irq+0x2e/0x6f
> > [  185.704529]  [<c0140098>]
> note_interrupt+0x1d3/0x207
> > [  185.704529]  [<c013f60e>] ?
> handle_IRQ_event+0x21/0x48
> > [  185.704529]  [<c01407c0>]
> handle_fasteoi_irq+0x8a/0xaa
> > [  185.704529]  [<c01056f2>] do_IRQ+0x71/0x8b
> > [  185.704529]  [<c010416b>]
> common_interrupt+0x23/0x28
> > [  185.704529]  [<c012007b>] ?
> prof_cpu_mask_write_proc+0xf/0x2f
> > [  185.704529]  [<c0103747>] ?
> sysenter_past_esp+0x38/0x91
> > [  185.704529]  =======================
> > [  185.704529] handlers:
> > [  185.704529] [<c03428d9>]
> (usb_hcd_irq+0x0/0x58)
> 
> Try adding a statement saying:
> 
> 	ehci_info(ehci, "irq status %x masked %x\n",
> status,
> 			status & INTR_MASK);
> 
> to ehci-hcd.c inside ehci_irq(), just before the line that
> does
> 
> 	status &= INTR_MASK;
> 
> Then let's see what happens.
> 
> Alan Stern
> 
> --
> To unsubscribe from this list: send the line
> "unsubscribe linux-kernel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at 
> http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at  http://www.tux.org/lkml/


      

USB Serial device disconnect causes IRQ disable after using ehci_info

[amruth]

Hi
Alan
I have observed that IRQ status has changed to c028, how do I decode the irq status. This causes the IRQ disabled.Detailed log is below.

[  469.393023] ehci_hcd 0000:00:1d.7: irq status c028 masked 20
[  507.575453] ehci_hcd 0000:00:1d.7: irq status 600b masked 3
[  507.575465] ehci_hcd 0000:00:1d.7: devpath 2 ep2in 3strikes

Thanks
Amruth p.v


--- On Mon, 8/25/08, amruth <amruth_pv@yahoo.com> wrote:

> From: amruth <amruth_pv@yahoo.com>
> Subject: USB Serial device disconnect causes IRQ disable after using ehci_info
> To: "Alan Stern" <stern@rowland.harvard.edu>
> Cc: "Oliver Neukum" <oliver@neukum.org>, linux-usb@vger.kernel.org, linux-kernel@vger.kernel.org
> Date: Monday, August 25, 2008, 4:12 PM
> Hi
> Alan
> 
> > That was the full-speed device.  Does it make any
> > difference if you use 
> > only one of them instead of both?
> > 
> The problem is seen when both are used.
> 
> > Try adding a statement saying:
> > 
> >ehci_info(ehci, "irq status %x masked
> %x\n",
> > status,
> >status & INTR_MASK);
> >> to ehci-hcd.c inside ehci_irq(), just before the
> line that
> > does 	status &= INTR_MASK;
> > 
> > Then let's see what happens.
> Here is the output after using ehci_info
> 
> [  310.517577] usbcore: registered new interface driver
> usbserial
> [  310.519417] usbserial: USB Serial support registered for
> generic
> [  310.521129] usbcore: registered new interface driver
> usbserial_generic
> [  310.521141] usbserial: USB Serial Driver core
> [  310.600476] usbserial: USB Serial support registered for
> TI USB 3410 1 port adapter
> [  310.602481] usbserial: USB Serial support registered for
> TI USB 5052 2 port adapter
> [  310.602481] usbcore: registered new interface driver
> ti_usb_3410_5052
> [  310.602481] ti_usb_3410_5052: TI USB 3410/5052 Serial
> Driver v0.9
> [  416.344945] ehci_hcd 0000:00:1d.7: irq status c masked 4
> [  416.344982] hub 5-0:1.0: state 7 ports 8 chg 0000 evt
> 0020
> [  416.344994] ehci_hcd 0000:00:1d.7: GetStatus port 5
> status 001803 POWER sig=j CSC CONNECT
> [  416.345005] hub 5-0:1.0: port 5, status 0501, change
> 0001, 480 Mb/s
> [  416.448335] hub 5-0:1.0: debounce: port 5: total 100ms
> stable 100ms status 0x501
> [  416.499523] ehci_hcd 0000:00:1d.7: port 5 full speed
> --> companion
> [  416.499533] ehci_hcd 0000:00:1d.7: GetStatus port 5
> status 003801 POWER OWNER sig=j CONNECT
> [  416.499547] usb usb3: wakeup_rh (auto-start)
> [  416.499565] hub 5-0:1.0: port 5 not reset yet, waiting
> 50ms
> [  416.503458] ehci_hcd 0000:00:1d.7: irq status c masked 4
> [  416.550314] ehci_hcd 0000:00:1d.7: GetStatus port 5
> status 003002 POWER OWNER sig=se0 CSC
> [  416.550353] hub 3-0:1.0: state 7 ports 2 chg 0000 evt
> 0002
> [  416.550366] uhci_hcd 0000:00:1d.2: port 1 portsc 0093,00
> [  416.550379] hub 3-0:1.0: port 1, status 0101, change
> 0001, 12 Mb/s
> [  416.654286] hub 3-0:1.0: debounce: port 1: total 100ms
> stable 100ms status 0x101
> [  416.756259] usb 3-1: new full speed USB device using
> uhci_hcd and address 2
> [  416.876237] usb 3-1: ep0 maxpacket = 8
> [  416.899501] usb 3-1: default language 0x0409
> [  416.914558] usb 3-1: uevent
> [  416.914605] usb 3-1: usb_probe_device
> [  416.914612] usb 3-1: configuration #1 chosen from 1
> choice
> [  416.917621] usb 3-1: adding 3-1:1.0 (config #1,
> interface 0)
> [  416.917683] usb 3-1:1.0: uevent
> [  416.917944] usbserial_generic 3-1:1.0:
> usb_probe_interface
> [  416.917950] usbserial_generic 3-1:1.0:
> usb_probe_interface - got id
> [  416.920536] drivers/usb/core/inode.c: creating file
> '002'
> [  416.920736] usb 3-1: New USB device found,
> idVendor=0801, idProduct=000a
> [  416.920742] usb 3-1: New USB device strings: Mfr=1,
> Product=2, SerialNumber=0
> [  416.920749] usb 3-1: Product: IntelliStripe 65
> [  416.920753] usb 3-1: Manufacturer: MagTek
> [  416.920762] hub 5-0:1.0: state 7 ports 8 chg 0000 evt
> 0020
> [  417.604928] usbserial: USB Serial support registered for
> Magtek 75/Excella USB card reader
> [  417.606929] magtek 3-1:1.0: usb_probe_interface
> [  417.606929] magtek 3-1:1.0: usb_probe_interface - got id
> [  417.606929] magtek 3-1:1.0: Magtek 75/Excella USB card
> reader converter detected
> [  417.606929] drivers/usb/serial/magtek.c: magtek_startup
> [  417.606929] uhci_hcd 0000:00:1d.2: reserve dev 2
> ep81-INT, period 8, phase 4, 61 us
> [  417.606929] drivers/usb/serial/magtek.c: magtek_startup
> - usb_submit_urb(int urb)
> [  417.606929] usb 3-1: Magtek 75/Excella USB card reader
> converter now attached to ttyUSB0
> [  417.607927] usbcore: registered new interface driver
> magtek
> [  417.607927] magtek: v1.01 Amruth Vamadev
> [  417.607927] magtek: MAGTEK 75/Excella check USB Chipcard
> Reader Driver
> [  469.065999] ehci_hcd 0000:00:1d.7: irq status c masked 4
> [  469.066035] hub 5-0:1.0: state 7 ports 8 chg 0000 evt
> 0004
> [  469.066045] ehci_hcd 0000:00:1d.7: GetStatus port 2
> status 001803 POWER sig=j CSC CONNECT
> [  469.066056] hub 5-0:1.0: port 2, status 0501, change
> 0001, 480 Mb/s
> [  469.169441] hub 5-0:1.0: debounce: port 2: total 100ms
> stable 100ms status 0x501
> [  469.220697] ehci_hcd 0000:00:1d.7: port 2 high speed
> [  469.220708] ehci_hcd 0000:00:1d.7: GetStatus port 2
> status 001005 POWER sig=se0 PE CONNECT
> [  469.271415] usb 5-2: new high speed USB device using
> ehci_hcd and address 4
> [  469.272398] ehci_hcd 0000:00:1d.7: irq status 8009
> masked 1
> [  469.276912] ehci_hcd 0000:00:1d.7: irq status 8028
> masked 20
> [  469.323607] ehci_hcd 0000:00:1d.7: port 2 high speed
> [  469.323617] ehci_hcd 0000:00:1d.7: GetStatus port 2
> status 001005 POWER sig=se0 PE CONNECT
> [  469.374478] ehci_hcd 0000:00:1d.7: irq status 8009
> masked 1
> [  469.374601] ehci_hcd 0000:00:1d.7: irq status 8028
> masked 20
> [  469.387239] ehci_hcd 0000:00:1d.7: irq status 8009
> masked 1
> [  469.387365] ehci_hcd 0000:00:1d.7: irq status 8009
> masked 1
> [  469.387414] ehci_hcd 0000:00:1d.7: irq status 8009
> masked 1
> [  469.387460] ehci_hcd 0000:00:1d.7: irq status 8009
> masked 1
> [  469.387513] usb 5-2: default language 0x0409
> [  469.387710] ehci_hcd 0000:00:1d.7: irq status 8009
> masked 1
> [  469.387836] ehci_hcd 0000:00:1d.7: irq status 8009
> masked 1
> [  469.387960] ehci_hcd 0000:00:1d.7: irq status 8009
> masked 1
> [  469.388033] usb 5-2: uevent
> [  469.388101] usb 5-2: usb_probe_device
> [  469.388108] usb 5-2: configuration #1 chosen from 1
> choice
> [  469.388211] ehci_hcd 0000:00:1d.7: irq status 8009
> masked 1
> [  469.388336] usb 5-2: adding 5-2:1.0 (config #1,
> interface 0)
> [  469.388385] usb 5-2:1.0: uevent
> [  469.388429] usbserial_generic 5-2:1.0:
> usb_probe_interface
> [  469.388435] usbserial_generic 5-2:1.0:
> usb_probe_interface - got id
> [  469.388454] magtek 5-2:1.0: usb_probe_interface
> [  469.388458] magtek 5-2:1.0: usb_probe_interface - got id
> [  469.388496] magtek 5-2:1.0: Magtek 75/Excella USB card
> reader converter detected
> [  469.388508] drivers/usb/serial/magtek.c: magtek_startup
> [  469.388663] usb 5-2: link qh0-00ff/ded71100 start 0 [1/0
> us]
> [  469.388719] drivers/usb/serial/magtek.c: magtek_startup
> - usb_submit_urb(int urb)
> [  469.388835] usb 5-2: Magtek 75/Excella USB card reader
> converter now attached to ttyUSB1
> [  469.389651] drivers/usb/core/inode.c: creating file
> '004'
> [  469.389759] usb 5-2: New USB device found,
> idVendor=0801, idProduct=2231
> [  469.389766] usb 5-2: New USB device strings: Mfr=1,
> Product=2, SerialNumber=3
> [  469.389772] usb 5-2: Product: STX
> [  469.389777] usb 5-2: Manufacturer: MagTek
> [  469.389781] usb 5-2: SerialNumber: STX001
> [  469.393023] ehci_hcd 0000:00:1d.7: irq status c028
> masked 20
> [  507.575453] ehci_hcd 0000:00:1d.7: irq status 600b
> masked 3
> [  507.575465] ehci_hcd 0000:00:1d.7: devpath 2 ep2in
> 3strikes
> [  507.575470] drivers/usb/serial/magtek.c:
> magtek_read_int_callback - port 1
> [  507.575484] usb 5-2: unlink qh0-00ff/ded71100 start 0
> [1/0 us]
> [  507.576084] usb 5-2: link qh0-00ff/ded71100 start 0 [1/0
> us]
> [  507.576548] usb 5-2: unlink qh0-00ff/ded71100 start 0
> [1/0 us]
> [  507.576548] ehci_hcd 0000:00:1d.7: HC died; cleaning up
> [  507.579131] hub 5-0:1.0: state 0 ports 8 chg 0000 evt
> 0000
> [  507.579137] usb 5-2: USB disconnect, address 4
> [  507.579141] usb 5-2: unregistering device
> [  507.579145] usb 5-2: usb_disable_device nuking all URBs
> [  507.579155] usb 5-2: unregistering interface 5-2:1.0
> [  507.579261] drivers/usb/serial/magtek.c: magtek_shutdown
> [  507.579418] magtek ttyUSB1: Magtek 75/Excella USB card
> reader converter now disconnected from ttyUSB1
> [  507.579450] magtek 5-2:1.0: device disconnected
> [  507.579464] usb 5-2:1.0: uevent
> [  507.581083] usb 5-2: uevent
> [  507.877032] irq 23: nobody cared (try booting with the
> "irqpoll" option)
> [  507.877042] Pid: 0, comm: swapper Not tainted
> 2.6.26patched #2
> [  507.877063]  [<c044c0cc>]
> __report_bad_irq+0x2e/0x6f
> [  507.877078]  [<c044c2e4>]
> note_interrupt+0x1d7/0x20b
> [  507.877089]  [<c044b852>] ?
> handle_IRQ_event+0x21/0x48
> [  507.877103]  [<c044ca0f>]
> handle_fasteoi_irq+0x8b/0xac
> [  507.877114]  [<c044c984>] ?
> handle_fasteoi_irq+0x0/0xac
> [  507.877123]  [<c040598c>] do_IRQ+0xa9/0xd1
> [  507.877131]  [<c04025f2>] ? default_idle+0x0/0x42
> [  507.877142]  [<c040429b>]
> common_interrupt+0x23/0x28
> [  507.877148]  [<c04025f2>] ? default_idle+0x0/0x42
> [  507.877167]  [<c040261f>] ? default_idle+0x2d/0x42
> [  507.877178]  [<c040256d>] cpu_idle+0x8b/0x9f
> [  507.877187]  [<c0610d62>] rest_init+0x4e/0x50
> [  507.877204]  =======================
> [  507.877207] handlers:
> [  507.877209] [<c057649d>] (usb_hcd_irq+0x0/0x58)
> [  507.877217] Disabling IRQ #23
> 
> 
> Thanks
> Amruth p.v
> 
> 
> --- On Mon, 8/25/08, Alan Stern
> <stern@rowland.harvard.edu> wrote:
> 
> > From: Alan Stern <stern@rowland.harvard.edu>
> > Subject: Re: USB Serial device disconnect causes IRQ
> disable not working after patch
> > To: "amruth" <amruth_pv@yahoo.com>
> > Cc: "Oliver Neukum"
> <oliver@neukum.org>, linux-usb@vger.kernel.org,
> linux-kernel@vger.kernel.org
> > Date: Monday, August 25, 2008, 1:50 PM
> > On Mon, 25 Aug 2008, amruth wrote:
> > 
> > > Hi
> > > Alan
> > > The patch suggested by you did not work. I tried
> in
> > another computer and found same issue. I have detailed
> log
> > below.
> > 
> > This log shows you have 2 Magtek devices: one running
> at
> > high speed and 
> > one running at full speed:
> > 
> > > [  143.041808] hub 1-0:1.0: state 7 ports 6 chg
> 0000
> > evt 0002
> > > [  143.041808] ehci_hcd 0000:00:1d.7: GetStatus
> port 1
> > status 001803 POWER sig=j CSC CONNECT
> > > [  143.041808] hub 1-0:1.0: port 1, status 0501,
> > change 0001, 480 Mb/s
> > > [  143.168024] hub 1-0:1.0: debounce: port 1:
> total
> > 100ms stable 100ms status 0x501
> > > [  143.224309] ehci_hcd 0000:00:1d.7: port 1 high
> > speed
> > > [  143.224323] ehci_hcd 0000:00:1d.7: GetStatus
> port 1
> > status 001005 POWER sig=se0 PE CONNECT
> > > [  143.280021] usb 1-1: new high speed USB device
> > using ehci_hcd and address 4
> > > [  143.336281] ehci_hcd 0000:00:1d.7: port 1 high
> > speed
> > > [  143.336292] ehci_hcd 0000:00:1d.7: GetStatus
> port 1
> > status 001005 POWER sig=se0 PE CONNECT
> > > [  143.412650] usb 1-1: default language 0x0409
> > > [  143.413121] usb 1-1: uevent
> > > [  143.417056] usb 1-1: usb_probe_device
> > > [  143.417068] usb 1-1: configuration #1 chosen
> from 1
> > choice
> > > [  143.417361] usb 1-1: adding 1-1:1.0 (config
> #1,
> > interface 0)
> > > [  143.417422] usb 1-1:1.0: uevent
> > > [  143.417622] usbserial_generic 1-1:1.0:
> > usb_probe_interface
> > > [  143.417627] usbserial_generic 1-1:1.0:
> > usb_probe_interface - got id
> > > [  143.417646] magtek 1-1:1.0:
> usb_probe_interface
> > > [  143.417650] magtek 1-1:1.0:
> usb_probe_interface -
> > got id
> > > [  143.417659] magtek 1-1:1.0: Magtek 75/Excella
> USB
> > card reader converter detected
> > 
> > That was the high-speed device.
> > 
> > > [  148.765273] hub 1-0:1.0: state 7 ports 6 chg
> 0000
> > evt 0004
> > > [  148.765273] ehci_hcd 0000:00:1d.7: GetStatus
> port 2
> > status 001803 POWER sig=j CSC CONNECT
> > > [  148.765273] hub 1-0:1.0: port 2, status 0501,
> > change 0001, 480 Mb/s
> > > [  148.892021] hub 1-0:1.0: debounce: port 2:
> total
> > 100ms stable 100ms status 0x501
> > > [  148.948172] ehci_hcd 0000:00:1d.7: port 2 full
> > speed --> companion
> > > [  148.948184] ehci_hcd 0000:00:1d.7: GetStatus
> port 2
> > status 003801 POWER OWNER sig=j CONNECT
> > > [  148.948201] usb usb2: wakeup_rh (auto-start)
> > > [  148.948222] hub 1-0:1.0: port 2 not reset yet,
> > waiting 50ms
> > > [  149.004019] ehci_hcd 0000:00:1d.7: GetStatus
> port 2
> > status 003002 POWER OWNER sig=se0 CSC
> > > [  149.004054] hub 2-0:1.0: state 7 ports 2 chg
> 0000
> > evt 0004
> > > [  149.004065] uhci_hcd 0000:00:1d.0: port 2
> portsc
> > 0093,00
> > > [  149.004075] hub 2-0:1.0: port 2, status 0101,
> > change 0001, 12 Mb/s
> > > [  149.132021] hub 2-0:1.0: debounce: port 2:
> total
> > 100ms stable 100ms status 0x101
> > > [  149.244042] usb 2-2: new full speed USB device
> > using uhci_hcd and address 2
> > > [  149.376015] usb 2-2: ep0 maxpacket = 8
> > > [  149.399097] usb 2-2: default language 0x0409
> > > [  149.408004] usb 2-2: uevent
> > > [  149.418007] usb 2-2: usb_probe_device
> > > [  149.418019] usb 2-2: configuration #1 chosen
> from 1
> > choice
> > > [  149.421042] usb 2-2: adding 2-2:1.0 (config
> #1,
> > interface 0)
> > > [  149.421112] usb 2-2:1.0: uevent
> > > [  149.421158] usbserial_generic 2-2:1.0:
> > usb_probe_interface
> > > [  149.421163] usbserial_generic 2-2:1.0:
> > usb_probe_interface - got id
> > > [  149.421182] magtek 2-2:1.0:
> usb_probe_interface
> > > [  149.421186] magtek 2-2:1.0:
> usb_probe_interface -
> > got id
> > > [  149.421193] magtek 2-2:1.0: Magtek 75/Excella
> USB
> > card reader converter detected
> > 
> > That was the full-speed device.  Does it make any
> > difference if you use 
> > only one of them instead of both?
> > 
> > > [  185.704529] irq 23: nobody cared (try booting
> with
> > the "irqpoll" option)
> > > [  185.704529] Pid: 3505, comm: automount Not
> tainted
> > 2.6.26-KGDB #1
> > > [  185.704529]  [<c013fe84>]
> > __report_bad_irq+0x2e/0x6f
> > > [  185.704529]  [<c0140098>]
> > note_interrupt+0x1d3/0x207
> > > [  185.704529]  [<c013f60e>] ?
> > handle_IRQ_event+0x21/0x48
> > > [  185.704529]  [<c01407c0>]
> > handle_fasteoi_irq+0x8a/0xaa
> > > [  185.704529]  [<c01056f2>]
> do_IRQ+0x71/0x8b
> > > [  185.704529]  [<c010416b>]
> > common_interrupt+0x23/0x28
> > > [  185.704529]  [<c012007b>] ?
> > prof_cpu_mask_write_proc+0xf/0x2f
> > > [  185.704529]  [<c0103747>] ?
> > sysenter_past_esp+0x38/0x91
> > > [  185.704529]  =======================
> > > [  185.704529] handlers:
> > > [  185.704529] [<c03428d9>]
> > (usb_hcd_irq+0x0/0x58)
> > 
> > Try adding a statement saying:
> > 
> > 	ehci_info(ehci, "irq status %x masked
> %x\n",
> > status,
> > 			status & INTR_MASK);
> > 
> > to ehci-hcd.c inside ehci_irq(), just before the line
> that
> > does
> > 
> > 	status &= INTR_MASK;
> > 
> > Then let's see what happens.
> > 
> > Alan Stern
> > 
> > --
> > To unsubscribe from this list: send the line
> > "unsubscribe linux-kernel" in
> > the body of a message to majordomo@vger.kernel.org
> > More majordomo info at 
> > http://vger.kernel.org/majordomo-info.html
> > Please read the FAQ at  http://www.tux.org/lkml/
> 
> 
>       
> 
> --
> To unsubscribe from this list: send the line
> "unsubscribe linux-kernel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at 
> http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at  http://www.tux.org/lkml/


      

Re: USB Serial device disconnect causes IRQ disable after using ehci_info

[Alan Stern]

On Mon, 25 Aug 2008, amruth wrote:

> Hi
> Alan

Please don't include old email messages at the bottom of your own 
messages.  It's annoying to read them.

> > That was the full-speed device.  Does it make any
> > difference if you use 
> > only one of them instead of both?
> > 
> The problem is seen when both are used.

That doesn't answer my question.  I already know that the problem is 
seen when both are used; the log you included before proves that.

What I don't know is whether the problem is seen when you use only 
the high-speed device.  Is it?

> > Try adding a statement saying:
> > 
> >ehci_info(ehci, "irq status %x masked %x\n",
> > status,
> >status & INTR_MASK);
> >> to ehci-hcd.c inside ehci_irq(), just before the line that
> > does 	status &= INTR_MASK;
> > 
> > Then let's see what happens.
> Here is the output after using ehci_info

> [  469.389759] usb 5-2: New USB device found, idVendor=0801, idProduct=2231
> [  469.389766] usb 5-2: New USB device strings: Mfr=1, Product=2, SerialNumber=3
> [  469.389772] usb 5-2: Product: STX
> [  469.389777] usb 5-2: Manufacturer: MagTek
> [  469.389781] usb 5-2: SerialNumber: STX001
> [  469.393023] ehci_hcd 0000:00:1d.7: irq status c028 masked 20
> [  507.575453] ehci_hcd 0000:00:1d.7: irq status 600b masked 3
> [  507.575465] ehci_hcd 0000:00:1d.7: devpath 2 ep2in 3strikes
> [  507.575470] drivers/usb/serial/magtek.c: magtek_read_int_callback - port 1
> [  507.575484] usb 5-2: unlink qh0-00ff/ded71100 start 0 [1/0 us]
> [  507.576084] usb 5-2: link qh0-00ff/ded71100 start 0 [1/0 us]
> [  507.576548] usb 5-2: unlink qh0-00ff/ded71100 start 0 [1/0 us]
> [  507.576548] ehci_hcd 0000:00:1d.7: HC died; cleaning up

For some reason this "HC died" line doesn't appear in your previous 
log.  I wonder why not?

> I have observed that IRQ status has changed to c028, how do I decode the irq
> status. This causes the IRQ disabled.Detailed log is below.

No, you're wrong.  Look at the timestamps.  The status was c028 when 
you plugged in the device; it changed to 600b when you unplugged it.
This didn't cause the the IRQ to be disabled, but it is an indication 
of where the problem really lies.

To decode the IRQ status values you need to consult the EHCI 
specification, section 2.3.2.

We need more information to track this down farther.  Add three copies
of this statement:

	ehci_info(ehci, "hcd state %d\n", hcd->state);

to the ehci_irq() function: one just before the line that says

	/* PCI errors [4.15.2.4] */

then below that just before the line that says

	spin_unlock (&ehci->lock);

and then just before the line that says

	return IRQ_HANDLED;

Make one other change as well, also in ehci-hcd.c.  In the function 
handshake_on_error_set_halt(), change these lines:

	if (error)
		ehci_to_hcd(ehci)->state = HC_STATE_HALT;

to this:

	if (error) {
		ehci_to_hcd(ehci)->state = HC_STATE_HALT;
		ehci_err(ehci, "Handshake failed; controller halted\n");
		dump_stack();
	}

Maybe these will help us find where the problem comes from.

Alan Stern

USB Serial device disconnect causes IRQ disable after using ehci_info

[amruth]

Hi
Alan

> What I don't know is whether the problem is seen when
> you use only 
> the high-speed device.  Is it?

Yes. The problem is seen if I use only high speed device. 

>For some reason this "HC died" line doesn't
> appear in your previous 
> log.  I wonder why not?
It is becasue I have shown the log messages after "HC died".

I will add more debug messages as suggested, rebuild the kernel 
and let you know.

Thanks
Amruth p.v





      

USB Serial device disconnect causes IRQ disable after using ehci controller halted

[amruth]

Hi
Alan
I am posting below detail log after adding debug messages
[  307.695452] magtek 5-1:1.0: Magtek 75/Excella USB card reader converter detected
[  307.695452] drivers/usb/serial/magtek.c: magtek_startup
[  307.695452] usb 5-1: link qh0-00ff/ded67080 start 0 [1/0 us]
[  307.695452] drivers/usb/serial/magtek.c: magtek_startup - usb_submit_urb(int urb)
[  307.695452] usb 5-1: Magtek 75/Excella USB card reader converter now attached to ttyUSB0
[  307.695452] drivers/usb/core/inode.c: creating file '006'
[  307.696371] usb 5-1: New USB device found, idVendor=0801, idProduct=2231
[  307.696377] usb 5-1: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[  307.696383] usb 5-1: Product: STX
[  307.696387] usb 5-1: Manufacturer: MagTek
[  307.696391] usb 5-1: SerialNumber: STX001
[  307.700515] ehci_hcd 0000:00:1d.7: irq status c028 masked 20
[  307.700530] ehci_hcd 0000:00:1d.7: hcd state 1
[  307.700536] ehci_hcd 0000:00:1d.7: hcd state 1
[  307.700544] ehci_hcd 0000:00:1d.7: hcd state 1
[  308.850650] ehci_hcd 0000:00:1d.7: irq status 600b masked 3
[  308.850658] ehci_hcd 0000:00:1d.7: hcd state 1
[  308.850665] ehci_hcd 0000:00:1d.7: devpath 1 ep2in 3strikes
[  308.850670] drivers/usb/serial/magtek.c: magtek_read_int_callback - port 0
[  308.850683] usb 5-1: unlink qh0-00ff/ded67080 start 0 [1/0 us]
[  308.850846] usb 5-1: link qh0-00ff/ded67080 start 0 [1/0 us]
[  308.851537] usb 5-1: unlink qh0-00ff/ded67080 start 0 [1/0 us]
[  308.853487] ehci_hcd 0000:00:1d.7: handshake failed: controller halted
[  308.853487] Pid: 0, comm: swapper Not tainted 2.6.26EHCIDBG #3
[  308.853487]  [<e08405aa>] handshake_on_error_set_halt+0x45/0x51 [ehci_hcd]
[  308.853487]  [<e08405d6>] disable_periodic+0x20/0x40 [ehci_hcd]
[  308.853487]  [<e0841fb4>] ehci_work+0x5e6/0x6ad [ehci_hcd]
[  308.853487]  [<c0424230>] ? printk+0x15/0x17
[  308.853487]  [<e0845c7e>] ehci_irq+0x28a/0x2fd [ehci_hcd]
[  308.853487]  [<e090005d>] ? cdrom_newpc_intr+0x52e/0x544 [ide_cd_mod]
[  308.853487]  [<c042addd>] ? lock_timer_base+0x1f/0x3e
[  308.853487]  [<c05764c4>] usb_hcd_irq+0x27/0x58
[  308.853487]  [<c044b852>] handle_IRQ_event+0x21/0x48
[  308.853487]  [<c044c9fb>] handle_fasteoi_irq+0x77/0xac
[  308.853487]  [<c044c984>] ? handle_fasteoi_irq+0x0/0xac
[  308.853487]  [<c040598c>] do_IRQ+0xa9/0xd1
[  308.853487]  [<c04025f2>] ? default_idle+0x0/0x42
[  308.853487]  [<c040429b>] common_interrupt+0x23/0x28
[  308.853487]  [<c04025f2>] ? default_idle+0x0/0x42
[  308.853487]  [<c041007b>] ? acpi_save_state_mem+0xa/0x12b
[  308.853487]  [<c040261f>] ? default_idle+0x2d/0x42
[  308.853487]  [<c040256d>] cpu_idle+0x8b/0x9f
[  308.853487]  [<c061f329>] start_secondary+0x156/0x15b
[  308.853487]  =======================
[  308.853487] ehci_hcd 0000:00:1d.7: hcd state 0
[  308.853487] ehci_hcd 0000:00:1d.7: hcd state 0
[  308.853487] ehci_hcd 0000:00:1d.7: HC died; cleaning up
[  308.854983] hub 5-0:1.0: state 0 ports 8 chg 0000 evt 0000
[  308.854983] usb 5-1: USB disconnect, address 6
[  308.854983] usb 5-1: unregistering device
[  308.854983] usb 5-1: usb_disable_device nuking all URBs
[  308.854983] usb 5-1: unregistering interface 5-1:1.0
[  308.854983] drivers/usb/serial/magtek.c: magtek_shutdown
[  308.854983] magtek ttyUSB0: Magtek 75/Excella USB card reader converter now disconnected from ttyUSB0
[  308.854983] magtek 5-1:1.0: device disconnected
[  308.854983] usb 5-1:1.0: uevent
[  308.854983] usb 5-1: uevent
[  309.153998] irq 23: nobody cared (try booting with the "irqpoll" option)
[  309.154006] Pid: 0, comm: swapper Not tainted 2.6.26EHCIDBG #3
[  309.154027]  [<c044c0cc>] __report_bad_irq+0x2e/0x6f
[  309.154042]  [<c044c2e4>] note_interrupt+0x1d7/0x20b
[  309.154054]  [<c044b852>] ? handle_IRQ_event+0x21/0x48
[  309.154068]  [<c044ca0f>] handle_fasteoi_irq+0x8b/0xac
[  309.154078]  [<c044c984>] ? handle_fasteoi_irq+0x0/0xac
[  309.154087]  [<c040598c>] do_IRQ+0xa9/0xd1
[  309.154096]  [<c04025f2>] ? default_idle+0x0/0x42
[  309.154107]  [<c040429b>] common_interrupt+0x23/0x28
[  309.154112]  [<c04025f2>] ? default_idle+0x0/0x42
[  309.154132]  [<c040261f>] ? default_idle+0x2d/0x42
[  309.154579]  [<c040256d>] cpu_idle+0x8b/0x9f
[  309.154579]  [<c061f329>] start_secondary+0x156/0x15b
[  309.154579]  =======================
[  309.154579] handlers:
[  309.154579] [<c057649d>] (usb_hcd_irq+0x0/0x58)
[  309.154579] Disabling IRQ #23



Thanks
Amruth p.v





      

Re: USB Serial device disconnect causes IRQ disable after using ehci controller halted

[Alan Stern]

Karsten and Dave:

It looks like the logic in ehci-hcd's handshake_on_error_set_halt() 
needs to be revisited.

On Tue, 26 Aug 2008, amruth wrote:

> Hi
> Alan
> I am posting below detail log after adding debug messages

...
> [  308.850665] ehci_hcd 0000:00:1d.7: devpath 1 ep2in 3strikes
> [  308.850670] drivers/usb/serial/magtek.c: magtek_read_int_callback - port 0
> [  308.850683] usb 5-1: unlink qh0-00ff/ded67080 start 0 [1/0 us]
> [  308.850846] usb 5-1: link qh0-00ff/ded67080 start 0 [1/0 us]
> [  308.851537] usb 5-1: unlink qh0-00ff/ded67080 start 0 [1/0 us]
> [  308.853487] ehci_hcd 0000:00:1d.7: handshake failed: controller halted

The line above was a debugging message added specially for this test.  
The controller wasn't really halted, but hcd->state was set to 
HC_STATE_HALTED.

> [  308.853487] Pid: 0, comm: swapper Not tainted 2.6.26EHCIDBG #3
> [  308.853487]  [<e08405aa>] handshake_on_error_set_halt+0x45/0x51 [ehci_hcd]
> [  308.853487]  [<e08405d6>] disable_periodic+0x20/0x40 [ehci_hcd]
> [  308.853487]  [<e0841fb4>] ehci_work+0x5e6/0x6ad [ehci_hcd]
> [  308.853487]  [<c0424230>] ? printk+0x15/0x17
> [  308.853487]  [<e0845c7e>] ehci_irq+0x28a/0x2fd [ehci_hcd]
> [  308.853487]  [<e090005d>] ? cdrom_newpc_intr+0x52e/0x544 [ide_cd_mod]
> [  308.853487]  [<c042addd>] ? lock_timer_base+0x1f/0x3e
> [  308.853487]  [<c05764c4>] usb_hcd_irq+0x27/0x58
> [  308.853487]  [<c044b852>] handle_IRQ_event+0x21/0x48
> [  308.853487]  [<c044c9fb>] handle_fasteoi_irq+0x77/0xac
> [  308.853487]  [<c044c984>] ? handle_fasteoi_irq+0x0/0xac
> [  308.853487]  [<c040598c>] do_IRQ+0xa9/0xd1
> [  308.853487]  [<c04025f2>] ? default_idle+0x0/0x42
> [  308.853487]  [<c040429b>] common_interrupt+0x23/0x28
> [  308.853487]  [<c04025f2>] ? default_idle+0x0/0x42
> [  308.853487]  [<c041007b>] ? acpi_save_state_mem+0xa/0x12b
> [  308.853487]  [<c040261f>] ? default_idle+0x2d/0x42
> [  308.853487]  [<c040256d>] cpu_idle+0x8b/0x9f
> [  308.853487]  [<c061f329>] start_secondary+0x156/0x15b
> [  308.853487]  =======================
> [  308.853487] ehci_hcd 0000:00:1d.7: hcd state 0
> [  308.853487] ehci_hcd 0000:00:1d.7: hcd state 0
> [  308.853487] ehci_hcd 0000:00:1d.7: HC died; cleaning up
> [  308.854983] hub 5-0:1.0: state 0 ports 8 chg 0000 evt 0000
> [  308.854983] usb 5-1: USB disconnect, address 6
> [  308.854983] usb 5-1: unregistering device
> [  308.854983] usb 5-1: usb_disable_device nuking all URBs
> [  308.854983] usb 5-1: unregistering interface 5-1:1.0
> [  308.854983] drivers/usb/serial/magtek.c: magtek_shutdown
> [  308.854983] magtek ttyUSB0: Magtek 75/Excella USB card reader converter now disconnected from ttyUSB0
> [  308.854983] magtek 5-1:1.0: device disconnected
> [  308.854983] usb 5-1:1.0: uevent
> [  308.854983] usb 5-1: uevent
> [  309.153998] irq 23: nobody cared (try booting with the "irqpoll" option)

Simply setting hcd->state to HC_STATE_HALTED isn't a good idea,
especially in cases like this where the controller really _isn't_
halted.  Here it was still generating IRQs, leading to the "nobody
cared" problem on the last line of the log.

While it certainly would be a good idea to prevent the handshake 
failures from occurring in the first place -- Dave, aren't you working 
on a patch for that? -- we should also make sure that when they do 
occur, the controller gets reset properly.  And an error message should 
be printed in the log.

Alan Stern

Re: USB Serial device disconnect causes IRQ disable after using ehci controller halted

[David Brownell]

On Tuesday 26 August 2008, Alan Stern wrote:
> While it certainly would be a good idea to prevent the handshake 
> failures from occurring in the first place -- Dave, aren't you working 
> on a patch for that? -- we should also make sure that when they do 
> occur, the controller gets reset properly.  And an error message should 
> be printed in the log.

Like this?

Greg, please queue for 2.6.27 unless someone finds a
problem with this patch.


=========	SNIP!  SNIP!  SNIPPITY SNIP!
From: David Brownell <dbrownell@users.sourceforge.net>

I noticed that the "Refactor "if (handshake()) state = HC_STATE_HALT"
patch from earlier this year perpetuated a potential problem:  it can
mark the controller as halted when it's still running (but not acting
as, perhaps wrongly, expected).

That caused some hangs and crashes, rather than more polite failure
modes of a truly halted controller.  This patch forces a true halt,
and emits a (previously missing) diagnostic.

Signed-off-by: David Brownell <dbrownell@users.sourceforge.net>
---
 drivers/usb/host/ehci-hcd.c |   26 ++++++++++++++++----------
 1 file changed, 16 insertions(+), 10 deletions(-)

--- a/drivers/usb/host/ehci-hcd.c	2008-08-15 14:04:27.000000000 -0700
+++ b/drivers/usb/host/ehci-hcd.c	2008-08-15 14:04:36.000000000 -0700
@@ -145,16 +145,6 @@ static int handshake (struct ehci_hcd *e
 	return -ETIMEDOUT;
 }
 
-static int handshake_on_error_set_halt(struct ehci_hcd *ehci, void __iomem *ptr,
-				       u32 mask, u32 done, int usec)
-{
-	int error = handshake(ehci, ptr, mask, done, usec);
-	if (error)
-		ehci_to_hcd(ehci)->state = HC_STATE_HALT;
-
-	return error;
-}
-
 /* force HC to halt state from unknown (EHCI spec section 2.3) */
 static int ehci_halt (struct ehci_hcd *ehci)
 {
@@ -173,6 +163,22 @@ static int ehci_halt (struct ehci_hcd *e
 			  STS_HALT, STS_HALT, 16 * 125);
 }
 
+static int handshake_on_error_set_halt(struct ehci_hcd *ehci, void __iomem *ptr,
+				       u32 mask, u32 done, int usec)
+{
+	int error;
+
+	error = handshake(ehci, ptr, mask, done, usec);
+	if (error) {
+		ehci_halt(ehci);
+		ehci_to_hcd(ehci)->state = HC_STATE_HALT;
+		ehci_err(ehci, "force halt; handhake %p %08x %08x -> %d\n",
+			ptr, mask, done, error);
+	}
+
+	return error;
+}
+
 /* put TDI/ARC silicon into EHCI mode */
 static void tdi_reset (struct ehci_hcd *ehci)
 {

USB Serial device disconnect causes IRQ disable after using ehci controller halted

[amruth]

Hi
Alan/David
This patch below does not fix the issue it just stops IRQ being disabled but still ehci hcd crashes. Please let me know what could be causing the issue.Is the hardware having any issue.
The log is below
[  552.905001] magtek 5-2:1.0: Magtek 75/Excella USB card reader converter detected
[  552.905001] /usr/src/linux-2.6.26/drivers/usb/serial/magtek.c: magtek_startup
[  552.905001] usb 5-2: link qh0-00ff/d8f44080 start 0 [1/0 us]
[  552.905001] /usr/src/linux-2.6.26/drivers/usb/serial/magtek.c: magtek_startup - usb_submit_urb(int urb)
[  552.905001] usb 5-2: Magtek 75/Excella USB card reader converter now attached to ttyUSB0
[  552.905001] drivers/usb/core/inode.c: creating file '006'
[  552.905001] usb 5-2: New USB device found, idVendor=0801, idProduct=2231
[  552.905001] usb 5-2: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[  552.905025] usb 5-2: Product: STX
[  552.905030] usb 5-2: Manufacturer: MagTek
[  552.905035] usb 5-2: SerialNumber: STX001
[  552.909786] ehci_hcd 0000:00:1d.7: irq status c028 masked 20
[  552.909793] ehci_hcd 0000:00:1d.7: hcd state 1
[  552.909796] ehci_hcd 0000:00:1d.7: hcd state 1
[  552.909799] ehci_hcd 0000:00:1d.7: hcd state 1
[  558.654520] ehci_hcd 0000:00:1d.7: irq status 600f masked 7
[  558.654520] ehci_hcd 0000:00:1d.7: hcd state 1
[  558.654520] ehci_hcd 0000:00:1d.7: devpath 2 ep2in 3strikes
[  558.654520] /usr/src/linux-2.6.26/drivers/usb/serial/magtek.c: magtek_read_int_callback - port 0
[  558.654520] /usr/src/linux-2.6.26/drivers/usb/serial/magtek.c: return!!
[  558.654520] /usr/src/linux-2.6.26/drivers/usb/serial/magtek.c: urb status is -71
[  558.654520] usb 5-2: unlink qh0-00ff/d8f44080 start 0 [1/0 us]
[  558.654520] usb 5-2: link qh0-00ff/d8f44080 start 0 [1/0 us]
[  558.654520] usb 5-2: unlink qh0-00ff/d8f44080 start 0 [1/0 us]
[  558.656520] ehci_hcd 0000:00:1d.7: handshake failed: controller halted
[  558.656520] ehci_hcd 0000:00:1d.7: force halt; handshake e0840824 00004000 00004000 -> -110
[  558.656520] Pid: 0, comm: swapper Not tainted 2.6.26patched #2
[  558.656520]  [<e0b1e5e7>] handshake_on_error_set_halt+0x82/0x8c [ehci_hcd]
[  558.656520]  [<e0b1e611>] disable_periodic+0x20/0x40 [ehci_hcd]
[  558.656520]  [<e0b1ffef>] ehci_work+0x5e6/0x6ad [ehci_hcd]
[  558.656520]  [<c0424230>] ? printk+0x15/0x17
[  558.656520]  [<e0b23cb9>] ehci_irq+0x28a/0x2fd [ehci_hcd]
[  558.656520]  [<e096905d>] ? cdrom_newpc_intr+0x52e/0x544 [ide_cd_mod]
[  558.656520]  [<c042addd>] ? lock_timer_base+0x1f/0x3e
[  558.656520]  [<c05764c4>] usb_hcd_irq+0x27/0x58
[  558.656520]  [<c044b852>] handle_IRQ_event+0x21/0x48
[  558.656520]  [<c044c9fb>] handle_fasteoi_irq+0x77/0xac
[  558.656520]  [<c044c984>] ? handle_fasteoi_irq+0x0/0xac
[  558.656520]  [<c040598c>] do_IRQ+0xa9/0xd1
[  558.656520]  [<c04025f2>] ? default_idle+0x0/0x42
[  558.656520]  [<c040429b>] common_interrupt+0x23/0x28
[  558.656520]  [<c04025f2>] ? default_idle+0x0/0x42
[  558.656520]  [<c041007b>] ? acpi_save_state_mem+0xa/0x12b
[  558.656520]  [<c040261f>] ? default_idle+0x2d/0x42
[  558.656520]  [<c040256d>] cpu_idle+0x8b/0x9f
[  558.656520]  [<c061f329>] start_secondary+0x156/0x15b
[  558.656520]  =======================
[  558.656520] ehci_hcd 0000:00:1d.7: hcd state 0
[  558.656520] ehci_hcd 0000:00:1d.7: hcd state 0
[  558.656520] ehci_hcd 0000:00:1d.7: HC died; cleaning up
[  558.657583] hub 5-0:1.0: state 0 ports 8 chg 0000 evt 0000
[  558.657583] usb 5-2: USB disconnect, address 6
[  558.657583] usb 5-2: unregistering device
[  558.657583] usb 5-2: usb_disable_device nuking all URBs
[  558.657583] usb 5-2: unregistering interface 5-2:1.0
[  558.657583] /usr/src/linux-2.6.26/drivers/usb/serial/magtek.c: magtek_shutdown
[  558.657583] magtek ttyUSB0: Magtek 75/Excella USB card reader converter now disconnected from ttyUSB0
[  558.657584] magtek 5-2:1.0: device disconnected
[  558.657584] usb 5-2:1.0: uevent
[  558.658057] usb 5-2: uevent

Thanks
Amruth p.v


--- On Tue, 8/26/08, David Brownell <david-b@pacbell.net> wrote:

> From: David Brownell <david-b@pacbell.net>
> Subject: Re: USB Serial device disconnect causes IRQ disable after using ehci controller halted
> To: "Alan Stern" <stern@rowland.harvard.edu>
> Cc: "Karsten Wiese" <fzu@wemgehoertderstaat.de>, "amruth" <amruth_pv@yahoo.com>, "Oliver Neukum" <oliver@neukum.org>, "USB list" <linux-usb@vger.kernel.org>, "Kernel development list" <linux-kernel@vger.kernel.org>, "Greg KH" <greg@kroah.com>
> Date: Tuesday, August 26, 2008, 4:43 PM
> On Tuesday 26 August 2008, Alan Stern wrote:
> > While it certainly would be a good idea to prevent the
> handshake 
> > failures from occurring in the first place -- Dave,
> aren't you working 
> > on a patch for that? -- we should also make sure that
> when they do 
> > occur, the controller gets reset properly.  And an
> error message should 
> > be printed in the log.
> 
> Like this?
> 
> Greg, please queue for 2.6.27 unless someone finds a
> problem with this patch.
> 
> 
> =========	SNIP!  SNIP!  SNIPPITY SNIP!
> From: David Brownell
> <dbrownell@users.sourceforge.net>
> 
> I noticed that the "Refactor "if (handshake())
> state = HC_STATE_HALT"
> patch from earlier this year perpetuated a potential
> problem:  it can
> mark the controller as halted when it's still running
> (but not acting
> as, perhaps wrongly, expected).
> 
> That caused some hangs and crashes, rather than more polite
> failure
> modes of a truly halted controller.  This patch forces a
> true halt,
> and emits a (previously missing) diagnostic.
> 
> Signed-off-by: David Brownell
> <dbrownell@users.sourceforge.net>
> ---
>  drivers/usb/host/ehci-hcd.c |   26
> ++++++++++++++++----------
>  1 file changed, 16 insertions(+), 10 deletions(-)
> 
> --- a/drivers/usb/host/ehci-hcd.c	2008-08-15
> 14:04:27.000000000 -0700
> +++ b/drivers/usb/host/ehci-hcd.c	2008-08-15
> 14:04:36.000000000 -0700
> @@ -145,16 +145,6 @@ static int handshake (struct ehci_hcd
> *e
>  	return -ETIMEDOUT;
>  }
>  
> -static int handshake_on_error_set_halt(struct ehci_hcd
> *ehci, void __iomem *ptr,
> -				       u32 mask, u32 done, int usec)
> -{
> -	int error = handshake(ehci, ptr, mask, done, usec);
> -	if (error)
> -		ehci_to_hcd(ehci)->state = HC_STATE_HALT;
> -
> -	return error;
> -}
> -
>  /* force HC to halt state from unknown (EHCI spec section
> 2.3) */
>  static int ehci_halt (struct ehci_hcd *ehci)
>  {
> @@ -173,6 +163,22 @@ static int ehci_halt (struct ehci_hcd
> *e
>  			  STS_HALT, STS_HALT, 16 * 125);
>  }
>  
> +static int handshake_on_error_set_halt(struct ehci_hcd
> *ehci, void __iomem *ptr,
> +				       u32 mask, u32 done, int usec)
> +{
> +	int error;
> +
> +	error = handshake(ehci, ptr, mask, done, usec);
> +	if (error) {
> +		ehci_halt(ehci);
> +		ehci_to_hcd(ehci)->state = HC_STATE_HALT;
> +		ehci_err(ehci, "force halt; handhake %p %08x %08x
> -> %d\n",
> +			ptr, mask, done, error);
> +	}
> +
> +	return error;
> +}
> +
>  /* put TDI/ARC silicon into EHCI mode */
>  static void tdi_reset (struct ehci_hcd *ehci)
>  {
> 
> 
> --
> To unsubscribe from this list: send the line
> "unsubscribe linux-kernel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at 
> http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at  http://www.tux.org/lkml/


      

Re: USB Serial device disconnect causes IRQ disable after using ehci controller halted

[David Brownell]

On Tuesday 26 August 2008, amruth wrote:
> This patch below does not fix the issue it just stops IRQ being
> disabled but still ehci hcd crashes. 

That patch was only intended to address the issue of bogus error
handling.


> Please let me know what could be causing the issue.

If it's like the other case, I'd hope this patch would solve it.

Note that you also seem to be having hardware or firmware issues
with the peripheral you're connecting ... this won't change that
stuff at all.

- Dave

================ SNIP!
From: David Brownell <dbrownell@users.sourceforge.net>

As noted by Stefan Neis <Stefan.Neis@kobil.com>, we had a recent
regression with EHCI periodic transfers, in some (seemingly not
all that common) cases.

The root cause was that the schedule activation was only loosely
coupled to the addition or removal of transfers, so two different 
execution contexts could both think they had to deactivate (or
conversely activate) the schedule.  So this fix tightens that
coupling, managing it more like a refcount.

Signed-off-by: David Brownell <dbrownell@users.sourceforge.net>
---
 drivers/usb/host/ehci-sched.c |   32 ++++++++++++++------------------
 1 file changed, 14 insertions(+), 18 deletions(-)

--- a/drivers/usb/host/ehci-sched.c	2008-08-15 16:38:19.000000000 -0700
+++ b/drivers/usb/host/ehci-sched.c	2008-08-15 17:47:02.000000000 -0700
@@ -437,6 +437,9 @@ static int enable_periodic (struct ehci_
 	u32	cmd;
 	int	status;
 
+	if (ehci->periodic_sched++)
+		return 0;
+
 	/* did clearing PSE did take effect yet?
 	 * takes effect only at frame boundaries...
 	 */
@@ -461,6 +464,9 @@ static int disable_periodic (struct ehci
 	u32	cmd;
 	int	status;
 
+	if (--ehci->periodic_sched)
+		return 0;
+
 	/* did setting PSE not take effect yet?
 	 * takes effect only at frame boundaries...
 	 */
@@ -544,13 +550,10 @@ static int qh_link_periodic (struct ehci
 		: (qh->usecs * 8);
 
 	/* maybe enable periodic schedule processing */
-	if (!ehci->periodic_sched++)
-		return enable_periodic (ehci);
-
-	return 0;
+	return enable_periodic(ehci);
 }
 
-static void qh_unlink_periodic (struct ehci_hcd *ehci, struct ehci_qh *qh)
+static int qh_unlink_periodic(struct ehci_hcd *ehci, struct ehci_qh *qh)
 {
 	unsigned	i;
 	unsigned	period;
@@ -586,9 +589,7 @@ static void qh_unlink_periodic (struct e
 	qh_put (qh);
 
 	/* maybe turn off periodic schedule */
-	ehci->periodic_sched--;
-	if (!ehci->periodic_sched)
-		(void) disable_periodic (ehci);
+	return disable_periodic(ehci);
 }
 
 static void intr_deschedule (struct ehci_hcd *ehci, struct ehci_qh *qh)
@@ -1562,9 +1563,7 @@ itd_link_urb (
 	urb->hcpriv = NULL;
 
 	timer_action (ehci, TIMER_IO_WATCHDOG);
-	if (unlikely (!ehci->periodic_sched++))
-		return enable_periodic (ehci);
-	return 0;
+	return enable_periodic(ehci);
 }
 
 #define	ISO_ERRS (EHCI_ISOC_BUF_ERR | EHCI_ISOC_BABBLE | EHCI_ISOC_XACTERR)
@@ -1642,7 +1641,7 @@ itd_complete (
 	ehci_urb_done(ehci, urb, 0);
 	retval = true;
 	urb = NULL;
-	ehci->periodic_sched--;
+	(void) disable_periodic(ehci);
 	ehci_to_hcd(ehci)->self.bandwidth_isoc_reqs--;
 
 	if (unlikely (list_empty (&stream->td_list))) {
@@ -1951,9 +1950,7 @@ sitd_link_urb (
 	urb->hcpriv = NULL;
 
 	timer_action (ehci, TIMER_IO_WATCHDOG);
-	if (!ehci->periodic_sched++)
-		return enable_periodic (ehci);
-	return 0;
+	return enable_periodic(ehci);
 }
 
 /*-------------------------------------------------------------------------*/
@@ -2019,7 +2016,7 @@ sitd_complete (
 	ehci_urb_done(ehci, urb, 0);
 	retval = true;
 	urb = NULL;
-	ehci->periodic_sched--;
+	(void) disable_periodic(ehci);
 	ehci_to_hcd(ehci)->self.bandwidth_isoc_reqs--;
 
 	if (list_empty (&stream->td_list)) {
@@ -2243,8 +2240,7 @@ restart:
 			if (unlikely (modified)) {
 				if (likely(ehci->periodic_sched > 0))
 					goto restart;
-				/* maybe we can short-circuit this scan! */
-				disable_periodic(ehci);
+				/* short-circuit this scan */
 				now_uframe = clock;
 				break;
 			}

Re: USB Serial device disconnect causes IRQ disable after using ehci controller halted

[Greg KH]

On Tue, Aug 26, 2008 at 11:35:04PM -0700, David Brownell wrote:
> On Tuesday 26 August 2008, amruth wrote:
> > This patch below does not fix the issue it just stops IRQ being
> > disabled but still ehci hcd crashes. 
> 
> That patch was only intended to address the issue of bogus error
> handling.
> 
> 
> > Please let me know what could be causing the issue.
> 
> If it's like the other case, I'd hope this patch would solve it.
> 
> Note that you also seem to be having hardware or firmware issues
> with the peripheral you're connecting ... this won't change that
> stuff at all.
> 
> - Dave
> 
> ================ SNIP!
> From: David Brownell <dbrownell@users.sourceforge.net>
> 
> As noted by Stefan Neis <Stefan.Neis@kobil.com>, we had a recent
> regression with EHCI periodic transfers, in some (seemingly not
> all that common) cases.
> 
> The root cause was that the schedule activation was only loosely
> coupled to the addition or removal of transfers, so two different 
> execution contexts could both think they had to deactivate (or
> conversely activate) the schedule.  So this fix tightens that
> coupling, managing it more like a refcount.
> 
> Signed-off-by: David Brownell <dbrownell@users.sourceforge.net>

Do you want me to also apply this one?  If so, for .27 or .28?

thanks,

greg k-h

Re: USB Serial device disconnect causes IRQ disable after using ehci controller halted

[David Brownell]

On Wednesday 27 August 2008, Greg KH wrote:
> 
> > As noted by Stefan Neis <Stefan.Neis@kobil.com>, we had a recent
> > regression with EHCI periodic transfers, in some (seemingly not
> > all that common) cases.
> > 
> > The root cause was that the schedule activation was only loosely
> > coupled to the addition or removal of transfers, so two different 
> > execution contexts could both think they had to deactivate (or
> > conversely activate) the schedule.  So this fix tightens that
> > coupling, managing it more like a refcount.
> > 
> > Signed-off-by: David Brownell <dbrownell@users.sourceforge.net>
> 
> Do you want me to also apply this one?  If so, for .27 or .28?

It should get into 2.6.27, and probably 26.stable ... assuming
that it checks out properly.  A somewhat cruftier version resolved
Stefan's problem, but I'd rather not merge that one.  Hmm, I'll
ask Stefan to confirm this version.

- Dave