Hi Alan,
sorry I couldn't resists and post yet another attempt, this time 3.3.2 kernel. ;)
I think I have some news, good news (at least for me). ;-)
Alan Stern wrote:
> On Thu, 12 Apr 2012, Martin Mokrejs wrote:
>
>>> The message in your log says what happened:
>>>
>>>> hub 2-1.2:1.0: port 1 disabled by hub (EMI?), re-enabling...
>>>
>>> Some sort of electrical noise caused the second hub to disable the port
>>> that the keyboard was plugged into.
>>
>> I reproduced that again, but took 3.5" drive as I thought I am dealing with
>> some "undercurrent" situation ... The external drive has its own power source,
>> and turning it on and off does not trigger the issue. Only once, after I started
>> up the drive and while it was spinning up its plates I plugged in the eSATA cable:
>
>> Ah, /var/log/messages does not have all messages seen in dmesg(1). :( Are some
>> written with different priority/severity?
>
> Of course: the debug-level messages. That's part of the reason why I
> always recommend that people use dmesg instead of the system log files
> for kernel testing and debugging. In addition, the syslog daemon
> sometimes drops messages if too many arrive too quickly.
That is true. Thanks for the reminder.
>
>> ata6: exception Emask 0x10 SAct 0x0 SErr 0x4040000 action 0xe frozen
>> ata6: irq_stat 0x00000040, connection status changed
>> ata6: SError: { CommWake DevExch }
>> ata6: hard resetting link
>> hub 2-1.2:1.0: port 4 disabled by hub (EMI?), re-enabling...
>> usb 2-1.2.4: USB disconnect, device number 9
>
> Unfortunately, the external hub says that is disabled the port, but
> it gives no explanation of why it did so. The cause has to be some
> sort of electrical noise, i.e., signals appearing on the USB data lines
> at the wrong time.
>
>> Interesting. The external USB hub has its own power supply. So once it reset the
>> keyboard connection, now it reset the mouse. s it Linux making the external HUB
>> to reset do you think it is the external hub itself?
>
> Linux can't make the hub do that. This is entirely the hub's doing.
I unplugged an eSATA drive from my eSATA/USB2 port aiming to plugin another one.
That immediately was recognized and the eSATA port disabled.
ata6: exception Emask 0x50 SAct 0x0 SErr 0x4090800 action 0xe frozen
ata6: irq_stat 0x00400040, connection status changed
ata6: SError: { HostInt PHYRdyChg 10B8B DevExch }
ata6: hard resetting link
ata6: SATA link down (SStatus 0 SControl 300)
ata6: hard resetting link
ata6: SATA link down (SStatus 0 SControl 300)
ata6: limiting SATA link speed to 1.5 Gbps
ata6: hard resetting link
ata6: SATA link down (SStatus 0 SControl 310)
ata6.00: disabled
ata6: EH complete
ata6.00: detaching (SCSI 5:0:0:0)
sd 5:0:0:0: [sdd] Synchronizing SCSI cache
sd 5:0:0:0: [sdd] Result: hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK
sd 5:0:0:0: [sdd] Stopping disk
sd 5:0:0:0: [sdd] START_STOP FAILED
sd 5:0:0:0: [sdd] Result: hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK
I plugged in several times *another* SATA drive into the eSATA port. It just
wasn't detected. No matter whether I turned on power first and then connected
the eSATA cable, or vice versa. Then I picked up the drive which was previously
in the eSATA port, and voila ...
generic-usb 0003:04F2:0116.0007: can't reset device, 0000:00:1d.0-1.2.1/input0, status -71
generic-usb 0003:046D:C050.0008: can't reset device, 0000:00:1d.0-1.2.4/input0, status -71
generic-usb 0003:04F2:0116.0007: can't reset device, 0000:00:1d.0-1.2.1/input0, status -71
generic-usb 0003:046D:C050.0008: can't reset device, 0000:00:1d.0-1.2.4/input0, status -71
generic-usb 0003:04F2:0116.0007: can't reset device, 0000:00:1d.0-1.2.1/input0, status -71
generic-usb 0003:046D:C050.0008: can't reset device, 0000:00:1d.0-1.2.4/input0, status -71
generic-usb 0003:04F2:0116.0007: can't reset device, 0000:00:1d.0-1.2.1/input0, status -71
generic-usb 0003:046D:C050.0008: can't reset device, 0000:00:1d.0-1.2.4/input0, status -71
generic-usb 0003:04F2:0116.0007: can't reset device, 0000:00:1d.0-1.2.1/input0, status -71
generic-usb 0003:046D:C050.0008: can't reset device, 0000:00:1d.0-1.2.4/input0, status -71
generic-usb 0003:04F2:0116.0007: can't reset device, 0000:00:1d.0-1.2.1/input0, status -71
generic-usb 0003:046D:C050.0008: can't reset device, 0000:00:1d.0-1.2.4/input0, status -71
generic-usb 0003:04F2:0116.0007: can't reset device, 0000:00:1d.0-1.2.1/input0, status -71
generic-usb 0003:046D:C050.0008: can't reset device, 0000:00:1d.0-1.2.4/input0, status -71
generic-usb 0003:04F2:0116.0007: can't reset device, 0000:00:1d.0-1.2.1/input0, status -71
generic-usb 0003:046D:C050.0008: can't reset device, 0000:00:1d.0-1.2.4/input0, status -71
generic-usb 0003:04F2:0116.0007: can't reset device, 0000:00:1d.0-1.2.1/input0, status -71
generic-usb 0003:046D:C050.0008: can't reset device, 0000:00:1d.0-1.2.4/input0, status -71
generic-usb 0003:04F2:0116.0007: can't reset device, 0000:00:1d.0-1.2.1/input0, status -71
generic-usb 0003:046D:C050.0008: can't reset device, 0000:00:1d.0-1.2.4/input0, status -71
hub 2-1.2:1.0: port 1 disabled by hub (EMI?), re-enabling...
usb 2-1.2.1: USB disconnect, device number 13
generic-usb 0003:046D:C050.0008: can't reset device, 0000:00:1d.0-1.2.4/input0, status -71
generic-usb 0003:046D:C050.0008: can't reset device, 0000:00:1d.0-1.2.4/input0, status -71
generic-usb 0003:046D:C050.0008: can't reset device, 0000:00:1d.0-1.2.4/input0, status -71
generic-usb 0003:046D:C050.0008: can't reset device, 0000:00:1d.0-1.2.4/input0, status -71
generic-usb 0003:046D:C050.0008: can't reset device, 0000:00:1d.0-1.2.4/input0, status -71
generic-usb 0003:046D:C050.0008: can't reset device, 0000:00:1d.0-1.2.4/input0, status -71
generic-usb 0003:046D:C050.0008: can't reset device, 0000:00:1d.0-1.2.4/input0, status -71
generic-usb 0003:046D:C050.0008: can't reset device, 0000:00:1d.0-1.2.4/input0, status -71
generic-usb 0003:046D:C050.0008: can't reset device, 0000:00:1d.0-1.2.4/input0, status -71
generic-usb 0003:046D:C050.0008: can't reset device, 0000:00:1d.0-1.2.4/input0, status -71
generic-usb 0003:046D:C050.0008: can't reset device, 0000:00:1d.0-1.2.4/input0, status -71
generic-usb 0003:046D:C050.0008: can't reset device, 0000:00:1d.0-1.2.4/input0, status -71
generic-usb 0003:046D:C050.0008: can't reset device, 0000:00:1d.0-1.2.4/input0, status -32
usb 2-1.2.1: new low-speed USB device number 16 using ehci_hcd
usb 2-1.2.1: New USB device found, idVendor=04f2, idProduct=0116
usb 2-1.2.1: New USB device strings: Mfr=1, Product=2, SerialNumber=0
usb 2-1.2.1: Product: USB Keyboard
usb 2-1.2.1: Manufacturer: CHICONY
input: CHICONY USB Keyboard as /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.2/2-1.2.1/2-1.2.1:1.0/input/input21
generic-usb 0003:04F2:0116.000A: input,hidraw0: USB HID v1.10 Keyboard [CHICONY USB Keyboard] on usb-0000:00:1d.0-1.2.1/input0
hub 2-1.2:1.0: port 4 disabled by hub (EMI?), re-enabling...
usb 2-1.2.4: USB disconnect, device number 14
usb 2-1.2.4: new low-speed USB device number 17 using ehci_hcd
usb 2-1.2.4: New USB device found, idVendor=046d, idProduct=c050
usb 2-1.2.4: New USB device strings: Mfr=1, Product=2, SerialNumber=0
usb 2-1.2.4: Product: USB-PS/2 Optical Mouse
usb 2-1.2.4: Manufacturer: Logitech
input: Logitech USB-PS/2 Optical Mouse as /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.2/2-1.2.4/2-1.2.4:1.0/input/input22
generic-usb 0003:046D:C050.000B: input,hidraw1: USB HID v1.10 Mouse [Logitech USB-PS/2 Optical Mouse] on usb-0000:00:1d.0-1.2.4/input0
Here is the same thing with time stamps (I was about 7 minutes trying to get the second
SATA disk recognized):
# tail -f /var/log/messages
Apr 14 15:34:22 vostro kernel: ata6: hard resetting link
Apr 14 15:34:22 vostro kernel: ata6: SATA link down (SStatus 0 SControl 310)
Apr 14 15:34:22 vostro kernel: ata6.00: disabled
Apr 14 15:34:23 vostro kernel: ata6: EH complete
Apr 14 15:34:23 vostro kernel: ata6.00: detaching (SCSI 5:0:0:0)
Apr 14 15:34:23 vostro kernel: sd 5:0:0:0: [sdd] Synchronizing SCSI cache
Apr 14 15:34:23 vostro kernel: sd 5:0:0:0: [sdd] Result: hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK
Apr 14 15:34:23 vostro kernel: sd 5:0:0:0: [sdd] Stopping disk
Apr 14 15:34:23 vostro kernel: sd 5:0:0:0: [sdd] START_STOP FAILED
Apr 14 15:34:23 vostro kernel: sd 5:0:0:0: [sdd] Result: hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK
[nothing deleted here, just for clarity some white space]
Apr 14 15:40:20 vostro kernel: usb 2-1.2.1: USB disconnect, device number 13
Apr 14 15:40:20 vostro kernel: usb 2-1.2.1: new low-speed USB device number 16 using ehci_hcd
Apr 14 15:40:20 vostro kernel: usb 2-1.2.1: New USB device found, idVendor=04f2, idProduct=0116
Apr 14 15:40:20 vostro kernel: usb 2-1.2.1: New USB device strings: Mfr=1, Product=2, SerialNumber=0
Apr 14 15:40:20 vostro kernel: usb 2-1.2.1: Product: USB Keyboard
Apr 14 15:40:20 vostro kernel: usb 2-1.2.1: Manufacturer: CHICONY
Apr 14 15:40:20 vostro kernel: input: CHICONY USB Keyboard as /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.2/2-1.2.1/2-1.2.1:1.0/input/input21
Apr 14 15:40:20 vostro kernel: generic-usb 0003:04F2:0116.000A: input,hidraw0: USB HID v1.10 Keyboard [CHICONY USB Keyboard] on usb-0000:00:1d.0-1.2.1/input0
Apr 14 15:40:20 vostro kernel: usb 2-1.2.4: USB disconnect, device number 14
Apr 14 15:40:20 vostro kernel: usb 2-1.2.4: new low-speed USB device number 17 using ehci_hcd
Apr 14 15:40:20 vostro kernel: usb 2-1.2.4: New USB device found, idVendor=046d, idProduct=c050
Apr 14 15:40:20 vostro kernel: usb 2-1.2.4: New USB device strings: Mfr=1, Product=2, SerialNumber=0
Apr 14 15:40:20 vostro kernel: usb 2-1.2.4: Product: USB-PS/2 Optical Mouse
Apr 14 15:40:20 vostro kernel: usb 2-1.2.4: Manufacturer: Logitech
Apr 14 15:40:20 vostro kernel: input: Logitech USB-PS/2 Optical Mouse as /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.2/2-1.2.4/2-1.2.4:1.0/input/input22
Apr 14 15:40:20 vostro kernel: generic-usb 0003:046D:C050.000B: input,hidraw1: USB HID v1.10 Mouse [Logitech USB-PS/2 Optical Mouse] on usb-0000:00:1d.0-1.2.4/input0
Hmm, But the eSATA port on the laptop is still disabled now. Oh, no, I did not
power on the "previous" disk yet. so I powered it on now (SATA cable was already
connected, and nothing happened). So, my eSATA port is somehow blocked, no matter
what disk I connect to it.
The USB reset was related to device 13 ... Hmm, that was the keyboard ... So the
kernel was chasing my keyboard? I have to admit I had yesterday problems with it
while testing 3.2.13/4 (unlike .12). First, when NumLock is ON numeric keys do the
opposite (so not numers, but PgUp, PgDn, etc. I don't remember having this issue before
and I would have ignored that if the device id would not belong to the keyboard.
Apr 14 07:41:03 vostro kernel: usb 2-1.2: new high-speed USB device number 12 using ehci_hcd
Apr 14 07:41:03 vostro kernel: usb 2-1.2: New USB device found, idVendor=05e3, idProduct=0608
Apr 14 07:41:03 vostro kernel: usb 2-1.2: New USB device strings: Mfr=0, Product=1, SerialNumber=0
Apr 14 07:41:03 vostro kernel: usb 2-1.2: Product: USB2.0 Hub
Apr 14 07:41:03 vostro kernel: hub 2-1.2:1.0: USB hub found
Apr 14 07:41:03 vostro kernel: hub 2-1.2:1.0: 4 ports detected
Apr 14 07:41:03 vostro kernel: usb 2-1.2.1: new low-speed USB device number 13 using ehci_hcd
Apr 14 07:41:03 vostro kernel: usb 2-1.2.1: New USB device found, idVendor=04f2, idProduct=0116
Apr 14 07:41:03 vostro kernel: usb 2-1.2.1: New USB device strings: Mfr=1, Product=2, SerialNumber=0
Apr 14 07:41:03 vostro kernel: usb 2-1.2.1: Product: USB Keyboard
Apr 14 07:41:03 vostro kernel: usb 2-1.2.1: Manufacturer: CHICONY
Apr 14 07:41:03 vostro kernel: input: CHICONY USB Keyboard as /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.2/2-1.2.1/2-1.2.1:1.0/input/input19
Apr 14 07:41:03 vostro kernel: generic-usb 0003:04F2:0116.0007: input,hidraw0: USB HID v1.10 Keyboard [CHICONY USB Keyboard] on usb-0000:00:1d.0-1.2.1/input0
Apr 14 07:41:04 vostro kernel: usb 2-1.2.4: new low-speed USB device number 14 using ehci_hcd
Apr 14 07:41:04 vostro kernel: usb 2-1.2.4: New USB device found, idVendor=046d, idProduct=c050
Apr 14 07:41:04 vostro kernel: usb 2-1.2.4: New USB device strings: Mfr=1, Product=2, SerialNumber=0
Apr 14 07:41:04 vostro kernel: usb 2-1.2.4: Product: USB-PS/2 Optical Mouse
Apr 14 07:41:04 vostro kernel: usb 2-1.2.4: Manufacturer: Logitech
Apr 14 07:41:04 vostro kernel: input: Logitech USB-PS/2 Optical Mouse as /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.2/2-1.2.4/2-1.2.4:1.0/input/input20
Apr 14 07:41:04 vostro kernel: generic-usb 0003:046D:C050.0008: input,hidraw1: USB HID v1.10 Mouse [Logitech USB-PS/2 Optical Mouse] on usb-0000:00:1d.0-1.2.4/input0
Alan, what do you think of the "EMI?" reset now?
Thank you for your patience,
Martin
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
