Re: bluetooth adapters keep disconnecting with an "USB disconnect"

Peter Kornatowski <pkorn@xxxxxxx> · Wed, 20 Jan 2010 00:10:36 +0100

At 23:09 18.01.2010, Alan Stern wrote:
On Mon, 18 Jan 2010, Peter Kornatowski wrote:

> >The timestamp is in microseconds from system startup; it doesn't give
> >the time of day.  If you can match up one of the events in the usbmon
> >log with something in the dmesg log then you can figure out the offset
> >between the two time scales.  Generally it doesn't matter.
>
> I know that it gives me the time from system startup, but the syslog
> gives me that, too. For example (*):
> Jan 17 03:36:36 peter kernel: [110056.795139] usb 3-2:
> uhci_result_common: failed with status 440000
> But as you can see the timestamp here (also in microseconds) has 12
> digits! But the usbmon log has even in the last lines (where the
> system was running over 15 hours) just 10 digits. I tried to grep for
> the whole timestamp from the syslog (then I got nothing) or just for
> the first 10 digits or the last 10 digits, but then it grepped way
> too many lines.

I just checked the source code, and it contains a bug.  The timestamp
value is intended to be the number of microseconds since startup,
modulo 4096 seconds.  That's so it will fit into 32 bits.

However in fact the calculation uses 65536 instead of 4096, and the
resulting overflow causes odd behavior.  (The computation is done in
hex instead of decimal, and the value used is 0xFFFF instead of 0xFFF.)

So to get an exact correspondence, begin with the number of seconds
since startup and divide by 65536.  Multiple the remainder by one
million, add in the additional microseconds, and take the low-order 32
bits of the result.  That's what the usbmon log contains.

Ok I did the math for the first timestamp (24951.136468) in the 
attached syslog_disconnect.log file. I got 3476299988 and grepped for 
it, but no line matched. So I grepped for " 3476299" (added a space 
before the first digit and cut the last 3 ones) and received what is 
in the attached file usbmon_timestamp.log. I Also grepped for 
"1:002:" and received what is in the attached file usbmon_1_002.log.
Hopefully this will help, thanks a lot!

> (*) This is from a test I ran over the weekend with no usb-devices at
> all, but just the 3 bluetooth-adapters (you asked for that). I got
> just one USB-disconnect in 65 hours of testing. So as I assumed,
> USB-hubs just increase the number of disconnects, but are not the
> cause. I attached the syslog of the disconnect.

The syslog makes it look exactly like a normal disconnect.  I suspect
that in the end this will turn out to be hardware problem with the
bluetooth adapters, like the problem Manuel described.

I ordered other bluetooth 2.1 and class 1 adapters and will make 
tests with them, too. Maybe it is simply a hardware problem...

Alan Stern

Best regards, Peter

--
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

Eingehende eMail ist virenfrei.
Von AVG uberpruft - www.avg.de
Version: 9.0.730 / Virendatenbank: 270.14.150/2632 - Ausgabedatum: 
01/19/10 08:34:00
dd87c0c0 3476299731 C Zi:1:016:4 0:1:927:0 1 0:0:22 22 = 02000200 01000200 0000ffff 01000300 01000200 fdff
dd87c0c0 3476299735 S Zi:1:016:4 -115:1:927 1 -18:0:24 24 <
dd9d7a00 3476299744 C Zo:1:009:3 0:1:925:0 3 0:0:17 0:17:17 0:34:17 51 >
de2da600 3476299748 C Zo:1:007:3 0:1:925:0 3 0:0:17 0:17:17 0:34:17 51 >
de2b8800 3476299 C Zo:1:007:3 0:1:866:0 3 0:0:17 0:17:17 0:34:17 51 >
dd7c7f40 3476299178 C Bi:1:010:8 0 56 = 45000038 f7db4000 3406c59e 5c4fb9b8 4d192625 6987bab0 7c946459 b9d74daf
dd7c7f40 3476299185 S Bi:1:010:8 -115 2048 <
dd87c0c0 3476299195 C Zi:1:016:4 0:1:575:0 1 0:0:22 22 = fcff0100 02000100 ffff0200 ffffffff faff0200 0100
dd87c0c0 3476299197 S Zi:1:016:4 -115:1:575 1 -18:0:24 24 <
de206e00 3476299203 C Zo:1:009:3 0:1:573:0 3 0:0:17 0:17:17 0:34:17 51 >
de206600 3476299207 C Zo:1:007:3 0:1:573:0 3 0:0:17 0:17:17 0:34:17 51 >
dd7c7d40 3476299248 S Bo:1:010:8 -115 52 = 45000034 ead44000 4006c6a9 4d192625 5c4fb9b8 bab06987 b9d74daf 7c94645d
dd7c7d40 3476299427 C Bo:1:010:8 0 52 >
deb72e00 3476299933 C Zo:1:008:3 0:1:574:0 3 0:0:17 0:17:17 0:34:17 51 >
dd7f18c0 347629909 C Bo:1:020:8 0 52 >
dd9d6a00 3476299388 C Zo:1:008:3 0:1:222:0 3 0:0:17 0:17:17 0:34:17 51 >
deac6f40 3476299635 C Zi:1:016:4 0:1:224:0 1 0:0:22 22 = fdff0200 05000100 ffff0100 fffffeff ffff0500 0400
deac6f40 3476299640 S Zi:1:016:4 -115:1:224 1 -18:0:24 24 <
deac6f40 3476299088 C Zi:1:016:4 0:1:896:0 1 0:0:22 22 = 02000300 01000000 02000300 feffffff 01000300 0100
deac6f40 3476299092 S Zi:1:016:4 -115:1:896 1 -18:0:24 24 <
deae5400 347629901 S Zo:1:008:3 -115:1:0 3 -18:0:17 -18:17:17 -18:34:17 51 = 2b003000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
de2611c0 3476299413 C Bi:1:015:1 0 2 = 1160
de2611c0 3476299421 S Bi:1:015:1 -115 512 <
deac6ec0 3476299432 C Zi:1:016:4 0:1:545:0 1 0:0:22 22 = fdff0100 ffff0000 0000feff 00000000 01000300 0400
deac6ec0 3476299435 S Zi:1:016:4 -115:1:545 1 -18:0:24 24 <
deac6ec0 3476299004 S Zi:1:016:4 -115:1:193 1 -18:0:24 24 <
df37f600 3476299010 C Zi:1:007:3 0:1:184:0 10 0:0:17 0:17:17 0:34:17 0:51:17 0:68:17 170 = 2a00301e 00170019 00140017 00250023 00180021 002c001f 001e001a 001e0023
df37f600 3476299017 S Zi:1:007:3 -115:1:184 10 -18:0:17 -18:17:17 -18:34:17 -18:51:17 -18:68:17 170 <
ddf00e00 3476299101 S Zo:1:007:3 -115:1:0 3 -18:0:17 -18:17:17 -18:34:17 51 = 2a003000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
de2dd600 3476299153 S Zo:1:007:3 -115:1:0 3 -18:0:17 -18:17:17 -18:34:17 51 = 2a003000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
deae4200 3476299202 S Zo:1:007:3 -115:1:0 3 -18:0:17 -18:17:17 -18:34:17 51 = 2a003000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
dd4dc4c0 3476299747 C Zo:1:016:2 0:1:187:0 8 0:0:64 0:64:64 0:128:64 0:192:64 0:256:64 512 >
dd4dc4c0 3476299753 S Zo:1:016:2 -115:1:187 8 -18:0:64 -18:64:64 -18:128:64 -18:192:64 -18:256:64 512 = 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
deac6e40 3476299994 C Zi:1:016:4 0:1:194:0 1 0:0:22 22 = 0000ffff ffff0100 feff0000 03000100 0100fdff fcff
deac6e40 3476299999 S Zi:1:016:4 -115:1:194 1 -18:0:24 24 <
dd4dc4c0 3476299201 C Zo:1:016:2 0:1:859:0 8 0:0:64 0:64:64 0:128:64 0:192:64 0:256:64 512 >
dd4dc4c0 3476299208 S Zo:1:016:2 -115:1:859 8 -18:0:64 -18:64:64 -18:128:64 -18:192:64 -18:256:64 512 = 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
deac6e40 3476299446 C Zi:1:016:4 0:1:866:0 1 0:0:22 22 = fbfffdff fdfffeff feffffff fffffeff 0100ffff ffff
deac6e40 3476299451 S Zi:1:016:4 -115:1:866 1 -18:0:24 24 <
dd993200 3476299458 C Zo:1:009:3 0:1:864:0 3 0:0:17 0:17:17 0:34:17 51 >
de2c4200 3476299462 C Zo:1:007:3 0:1:864:0 3 0:0:17 0:17:17 0:34:17 51 >
dde55e00 3476299010 S Zo:1:009:3 -115:1:0 3 -18:0:17 -18:17:17 -18:34:17 51 = 2a003000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
de148a00 3476299061 S Zo:1:009:3 -115:1:0 3 -18:0:17 -18:17:17 -18:34:17 51 = 2a003000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
dd993a00 3476299108 S Zo:1:009:3 -115:1:0 3 -18:0:17 -18:17:17 -18:34:17 51 = 2a003000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
dd47e600 3476299156 S Zo:1:009:3 -115:1:0 3 -18:0:17 -18:17:17 -18:34:17 51 = 2a003000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
dd87c2c0 3476299904 C Zi:1:016:4 0:1:515:0 1 0:0:22 22 = 08000600 04000200 fffffeff fbfffaff fbff0200 fdff
dd87c2c0 3476299910 S Zi:1:016:4 -115:1:515 1 -18:0:24 24 <
df3b9800 3476299918 C Zi:1:025:3 0:1:506:0 10 0:0:17 0:17:17 0:34:17 0:51:17 0:68:17 170 = 2b003021 00200014 001d0019 00150014 001e0023 00140017 0016000d 000d000b
df3b9800 3476299926 S Zi:1:025:3 -115:1:506 10 -18:0:17 -18:17:17 -18:34:17 -18:51:17 -18:68:17 170 <
ddaf8a00 3476299933 C Zo:1:025:3 0:1:513:0 3 0:0:17 0:17:17 0:34:17 51 >
df34d400 34762997 S Zo:1:007:3 -115:1:0 3 -18:0:17 -18:17:17 -18:34:17 51 = 2a003000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
dd87c2c0 3476299355 C Zi:1:016:4 0:1:163:0 1 0:0:22 22 = 00000300 04000200 04000300 02000200 0300ffff 0000
dd87c2c0 3476299359 S Zi:1:016:4 -115:1:163 1 -18:0:24 24 <
de14fe00 3476299365 C Zo:1:025:3 0:1:161:0 3 0:0:17 0:17:17 0:34:17 51 >
dd87c0c0 347629961 C Zi:1:016:4 0:1:223:0 1 0:0:22 22 = fcfffaff 00000200 05000100 01000100 0000ffff feff
dd87c0c0 347629966 S Zi:1:016:4 -115:1:223 1 -18:0:24 24 <
dd858000 347629973 C Zo:1:009:3 0:1:221:0 3 0:0:17 0:17:17 0:34:17 51 >
ddd8f200 347629977 C Zo:1:007:3 0:1:221:0 3 0:0:17 0:17:17 0:34:17 51 >
dd87c0c0 347629912 C Zi:1:016:4 0:1:767:0 1 0:0:22 22 = 0200fdff 01000100 03000400 0300feff feff0000 feff
dd87c0c0 347629918 S Zi:1:016:4 -115:1:767 1 -18:0:24 24 <
ddd8fc00 347629927 C Zo:1:009:3 0:1:765:0 3 0:0:17 0:17:17 0:34:17 51 >
de0c0200 347629931 C Zo:1:007:3 0:1:765:0 3 0:0:17 0:17:17 0:34:17 51 >
dd87c240 3476299762 C Zi:1:016:4 0:1:356:0 1 0:0:22 22 = fefffdff fefffeff fdff0100 feff0000 00000100 fdff
dd87c240 3476299767 S Zi:1:016:4 -115:1:356 1 -18:0:24 24 <
dd87c240 3476299213 C Zi:1:016:4 0:1:4:0 1 0:0:22 22 = fefffdff 02000000 03000300 fffffeff fdfffeff 0400
dd87c240 3476299217 S Zi:1:016:4 -115:1:4 1 -18:0:24 24 <
ddefe600 3476299223 C Zi:1:009:3 0:1:1019:0 10 0:0:17 0:17:17 0:34:17 0:51:17 0:68:17 170 = 2d002800 21001400 0e001e00 1c001500 0e001300 1a001800 1a000f00 0d001000
ddefe600 3476299231 S Zi:1:009:3 -115:1:1019 10 -18:0:17 -18:17:17 -18:34:17 -18:51:17 -18:68:17 170 <
de13fa00 3476299355 S Zo:1:009:3 -115:1:0 3 -18:0:17 -18:17:17 -18:34:17 51 = 2a003000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
df378400 3476299408 S Zo:1:009:3 -115:1:0 3 -18:0:17 -18:17:17 -18:34:17 51 = 2a003000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
de28a200 3476299456 S Zo:1:009:3 -115:1:0 3 -18:0:17 -18:17:17 -18:34:17 51 = 2a003000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
dd87c1c0 3476299666 C Zi:1:016:4 0:1:677:0 1 0:0:22 22 = 00000000 feff0200 0100ffff fcff0000 00000100 0100
dd87c1c0 3476299670 S Zi:1:016:4 -115:1:677 1 -18:0:24 24 <
dea98c00 3476299677 C Zo:1:009:3 0:1:675:0 3 0:0:17 0:17:17 0:34:17 51 >
de2e6e00 3476299680 C Zo:1:007:3 0:1:675:0 3 0:0:17 0:17:17 0:34:17 51 >
dd87c1c0 3476299120 C Zi:1:016:4 0:1:325:0 1 0:0:22 22 = 04000700 07000300 feff0000 fffffeff ffff0300 0200
dd87c1c0 3476299124 S Zi:1:016:4 -115:1:325 1 -18:0:24 24 <
dd495a00 3476299130 C Zo:1:009:3 0:1:323:0 3 0:0:17 0:17:17 0:34:17 51 >
dde55800 3476299134 C Zo:1:007:3 0:1:323:0 3 0:0:17 0:17:17 0:34:17 51 >
de108200 347629928 S Zo:1:027:3 -115:1:0 3 -18:0:17 -18:17:17 -18:34:17 51 = 2b003000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
dd87c140 3476299573 C Zi:1:016:4 0:1:998:0 1 0:0:22 22 = fdffffff 02000000 0300fdff fdff0100 03000400 0400
dd87c140 3476299577 S Zi:1:016:4 -115:1:998 1 -18:0:24 24 <
dd4dc4c0 347629928 C Zo:1:016:2 0:1:27:0 8 0:0:64 0:64:64 0:128:64 0:192:64 0:256:64 512 >
dd4dc4c0 347629934 S Zo:1:016:2 -115:1:27 8 -18:0:64 -18:64:64 -18:128:64 -18:192:64 -18:256:64 512 = 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
dd87c140 3476299029 C Zi:1:016:4 0:1:646:0 1 0:0:22 22 = fffffdff fdff0000 00000500 ffffffff fefffdff ffff
dd87c140 3476299038 S Zi:1:016:4 -115:1:646 1 -18:0:24 24 <
dd87c0c0 3476299478 C Zi:1:016:4 0:1:295:0 1 0:0:22 22 = 0000feff 00000300 00000100 0000ffff fcfffeff feff
dd87c0c0 3476299482 S Zi:1:016:4 -115:1:295 1 -18:0:24 24 <
df37f000 3476299488 C Zi:1:007:3 0:1:286:0 10 0:0:17 0:17:17 0:34:17 0:51:17 0:68:17 170 = 2a003011 00140022 00200019 001a001e 00110010 0023001e 000f001d 00270024
df37f000 3476299496 S Zi:1:007:3 -115:1:286 10 -18:0:17 -18:17:17 -18:34:17 -18:51:17 -18:68:17 170 <
dde7da00 3476299583 S Zo:1:007:3 -115:1:0 3 -18:0:17 -18:17:17 -18:34:17 51 = 2a003000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
debe6400 3476299635 S Zo:1:007:3 -115:1:0 3 -18:0:17 -18:17:17 -18:34:17 51 = 2a003000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
de008800 3476299684 S Zo:1:007:3 -115:1:0 3 -18:0:17 -18:17:17 -18:34:17 51 = 2a003000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
Attachment:
syslog_disconnect.log

Description: Binary data
Attachment:
usbmon_1_002.log

Description: Binary data