I have a late-model Intel 7260 wifi/bluetooth mini-PCIE card plugged into
my Nvidia Jetson board. Bluetooth is basically working, but I've noticed
the following odd pattern in my logs:
(previous 12 days omitted for brevity; pattern is same as below)
[...]
Aug 16 03:33:00 kolonia kernel: [921790.543197] usb 1-1: USB disconnect, device number 12
Aug 16 03:33:00 kolonia kernel: [921790.761151] usb 1-1: new full-speed USB device number 13 using tegra-ehci
Aug 16 03:33:00 kolonia kernel: [921790.889599] usb 1-1: New USB device found, idVendor=8087, idProduct=07dc
Aug 16 03:33:00 kolonia kernel: [921790.896428] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
Aug 16 03:33:00 kolonia kernel: [921790.922681] Bluetooth: hci0: read Intel version: 3707100180012d0d06
Aug 16 03:33:00 kolonia kernel: [921790.929091] Bluetooth: hci0: Intel device is already patched. patch num: 06
Aug 16 03:33:00 kolonia bluetoothd[1888]: Sap driver initialization failed.
Aug 16 03:33:00 kolonia bluetoothd[1888]: sap-server: Operation not permitted (1)
Aug 16 03:33:00 kolonia bluetoothd[1888]: Failed to set mode: Busy (0x0a)
[...]
Aug 18 02:09:13 kolonia kernel: [1089565.056222] usb 1-1: USB disconnect, device number 13
Aug 18 02:09:13 kolonia kernel: [1089565.271214] usb 1-1: new full-speed USB device number 14 using tegra-ehci
Aug 18 02:09:13 kolonia kernel: [1089565.400011] usb 1-1: New USB device found, idVendor=8087, idProduct=07dc
Aug 18 02:09:13 kolonia kernel: [1089565.406942] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
Aug 18 02:09:13 kolonia kernel: [1089565.431982] Bluetooth: hci0: read Intel version: 3707100180012d0d06
Aug 18 02:09:13 kolonia kernel: [1089565.438483] Bluetooth: hci0: Intel device is already patched. patch num: 06
Aug 18 02:09:13 kolonia bluetoothd[1888]: Sap driver initialization failed.
Aug 18 02:09:13 kolonia bluetoothd[1888]: sap-server: Operation not permitted (1)
Aug 18 02:09:13 kolonia bluetoothd[1888]: Failed to set mode: Busy (0x0a)
[...]
Aug 19 01:27:20 kolonia kernel: [1173452.517103] usb 1-1: USB disconnect, device number 14
Aug 19 01:27:20 kolonia kernel: [1173452.734122] usb 1-1: new full-speed USB device number 15 using tegra-ehci
Aug 19 01:27:20 kolonia kernel: [1173452.865078] usb 1-1: New USB device found, idVendor=8087, idProduct=07dc
Aug 19 01:27:20 kolonia kernel: [1173452.872018] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
Aug 19 01:27:20 kolonia kernel: [1173452.899169] Bluetooth: hci0: read Intel version: 3707100180012d0d06
Aug 19 01:27:20 kolonia kernel: [1173452.905689] Bluetooth: hci0: Intel device is already patched. patch num: 06
Aug 19 01:27:20 kolonia bluetoothd[1888]: Sap driver initialization failed.
Aug 19 01:27:20 kolonia bluetoothd[1888]: sap-server: Operation not permitted (1)
Aug 19 01:27:20 kolonia bluetoothd[1888]: Failed to set mode: Busy (0x0a)
The interval is very consistent at 23 hours, 18 minutes, and 7 seconds, plus
or minus a second. This happens almost every day, but you can see it skipped
August 17th for some reason. In that case the interval was exactly 2x, i.e.
the pattern continues.
Any idea why this would be happening? It doesn't seem to have any adverse
effects, but I like a good mystery.
Hi Mark,
After you replace the ibt-xxx.bseq file, you need to shut down your machine and reboot it (power off device). Then the controller will re-load the FW patch.
And you will find Bluetooth: hci0: read Intel version: 3707100180012d0da1
Bluetooth: hci0: Intel device is already patched. patch num: a1
Ethan
-----Original Message-----
From: [email protected] [mailto:[email protected]] On Behalf Of Mark Haun
Sent: Wednesday, August 26, 2015 12:53 AM
To: Ge, Ethan
Cc: [email protected]
Subject: Re: Intel 7260 spontaneous USB disconnect/reconnect every 23h18m07s
Hi Ethan,
Ge, Ethan [[email protected]] wrote:
> Your Intel FW version hci0: read Intel version: 3707100180012d0d06,
> it's too old. Please try latest Intel WP2 FW
> Ibt-hw-37.7.10-fw-1.80.1.2d.d.bseq in linux-firmware/intel.
So I tried this before going away for the weekend, rebooted, and then checked dmesg when I got back. The issue is still there, spontaneous disconnect/reconnect every 23h18m07s like clockwork.
I am starting to second-guess myself a little, though, because I am confused about the firmware naming. The firmware or microcode files I am familiar with (iwlwifi for instance) have the firmware version as part of the file name. The ibt-hw-* firmwares, on the other hand, appear to keep the *same* filename when new versions come out; only the increased file size indicates that the contents have changed. So I am guessing that the filename refers to the hardware revision it is intended for, rather than the firmware/microcode revision? Either that, or debian is not distributing the same firmware files as the ones in git!
In any case, the dmesg output with the [presumed correct] firmware is precisely the same as before:
Bluetooth: hci0: read Intel version: 3707100180012d0d06
Bluetooth: hci0: Intel device is already patched. patch num: 06
The size of the file "ibt-hw-37.7.10-fw-1.80.1.2d.d.bseq" is now 17310 bytes. That is larger than the one it overwrote, but I didn't write down the old size.
Kernel version is 4.2.0-rc4.
Mark
Marcel Holtmann [[email protected]] wrote:
> you can run bluemoon with -r switch additionally to any other command. It
> will use raw HCI access and it will also work when the device is up and
> bluetoothd already running.
Ok, that worked (interesting that every switch mentioned so far is
undocumented in 'bluemoon --help' :)
Hardware Platform: 55
Hardware Variant: iBT 2.0 (WP) (0x07)
Hardware Revision: 1.0
Firmware Variant: iBT 1.0 - iBT 2.5 (0x01)
Firmware Revision: 8.0
Firmware Build Number: 1-45.2013
Firmware Patch Number: 6
Of course, I have no way of knowing what the latest firmware is, and whether
I am running it or not.
As mentioned, I am on rc4 right now, so when I upgrade the kernel
"bluemoon -T" should work. 4.2.0 final should be out next weekend, so I may
wait for that.
In the meantime, I am going to watch dmesg with none of the bluez userspace
components running. I have a hunch the USB disconnect issue will still be
there...
Mark
Hi Mark,
>> Took me a while to figure out you have to bring down the hci0 interface and
>> stop bluetoothd before running bluemoon. Otherwise I get "Failed to open
>> HCI user channel." So now when I run bluemoon -T it just sits there forever
>> after the welcome message. Is this expected behavior? Should I then
>> restart bluetoothd in another console and leave the whole thing for a couple
>> of days to catch the USB disconnect?
>
> Ok, I think I am seeing a bug very similar to this one reported by Loic
> Poulain:
>
> http://marc.info/?l=linux-bluetooth&m=143220351521634&w=2
> ("bluetooth-next HCI user channel issue")
>
> I have the same symptom of bluemoon hanging, and I figured out that I can
> recover the system without rebooting by forcing hci0 down again. "hciconfig
> hci0 down" takes about ten seconds to return, and then I have a 0xfc3f
> timeout in dmesg:
>
> [ 5563.562554] Bluetooth: hci0 command 0xfc3f tx timeout
> [ 5571.557618] Bluetooth: hci0: turning off Intel device LED failed (-110)
>
> This is the same error Loic was getting, I assume because the commit in
> question has now made it into my kernel (4.2.0-rc4).
there are patches in 4.2-rc8 at least that should avoid this issue in combination with HCI User Channel. If this is still an issue, then we need to fix this.
Regards
Marcel
Hi Mark,
>> please run bluemoon -T to enable the LMP tracing feature and then see if
>> you happen to catch the messages before the controller jumps off the bus.
>> I wonder which side initiates the key refresh. Also what is the remote
>> device. You can try hcitool info <bdaddr> to get its features.
>
> Took me a while to figure out you have to bring down the hci0 interface and
> stop bluetoothd before running bluemoon. Otherwise I get "Failed to open
> HCI user channel." So now when I run bluemoon -T it just sits there forever
> after the welcome message. Is this expected behavior? Should I then
> restart bluetoothd in another console and leave the whole thing for a couple
> of days to catch the USB disconnect?
you can run bluemoon with -r switch additionally to any other command. It will use raw HCI access and it will also work when the device is up and bluetoothd already running.
Regards
Marcel
Mark Haun [[email protected]] wrote:
> Took me a while to figure out you have to bring down the hci0 interface and
> stop bluetoothd before running bluemoon. Otherwise I get "Failed to open
> HCI user channel." So now when I run bluemoon -T it just sits there forever
> after the welcome message. Is this expected behavior? Should I then
> restart bluetoothd in another console and leave the whole thing for a couple
> of days to catch the USB disconnect?
Ok, I think I am seeing a bug very similar to this one reported by Loic
Poulain:
http://marc.info/?l=linux-bluetooth&m=143220351521634&w=2
("bluetooth-next HCI user channel issue")
I have the same symptom of bluemoon hanging, and I figured out that I can
recover the system without rebooting by forcing hci0 down again. "hciconfig
hci0 down" takes about ten seconds to return, and then I have a 0xfc3f
timeout in dmesg:
[ 5563.562554] Bluetooth: hci0 command 0xfc3f tx timeout
[ 5571.557618] Bluetooth: hci0: turning off Intel device LED failed (-110)
This is the same error Loic was getting, I assume because the commit in
question has now made it into my kernel (4.2.0-rc4).
Mark
Hi Marcel,
Ok, it was easier than I expected to build bluez 5.33 so I went ahead and
tried this.
Marcel Holtmann [[email protected]] wrote:
> please run bluemoon -T to enable the LMP tracing feature and then see if
> you happen to catch the messages before the controller jumps off the bus.
> I wonder which side initiates the key refresh. Also what is the remote
> device. You can try hcitool info <bdaddr> to get its features.
Took me a while to figure out you have to bring down the hci0 interface and
stop bluetoothd before running bluemoon. Otherwise I get "Failed to open
HCI user channel." So now when I run bluemoon -T it just sits there forever
after the welcome message. Is this expected behavior? Should I then
restart bluetoothd in another console and leave the whole thing for a couple
of days to catch the USB disconnect?
> As I said before, just running bluemoon should decode the firmware version
> for you. No need to wildly guess.
I only seem to get one bluemoon invocation per boot, before the "Failed to
open HCI user channel" messages commence, so I haven't tried this yet...
Maybe on the next boot :)
Mark
Marcel Holtmann [[email protected]] wrote:
> > [83894.699185] usb 1-1: USB disconnect, device number 2
> > [83894.914720] usb 1-1: new full-speed USB device number 3 using tegra-ehci
> > [83895.044528] usb 1-1: New USB device found, idVendor=8087, idProduct=07dc
> > [83895.051304] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
> > [83895.076633] Bluetooth: hci0: read Intel version: 3707100180012d0d06
> > [83895.082944] Bluetooth: hci0: Intel device is already patched. patch num: 06
> > [167782.187624] usb 1-1: USB disconnect, device number 3
> > [167782.403343] usb 1-1: new full-speed USB device number 4 using tegra-ehci
> > [167782.532645] usb 1-1: New USB device found, idVendor=8087, idProduct=07dc
> > [167782.539504] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
> > [167782.564803] Bluetooth: hci0: read Intel version: 3707100180012d0d06
> > [167782.571242] Bluetooth: hci0: Intel device is already patched. patch num: 06
>
> please run bluemoon -T to enable the LMP tracing feature and then see if
> you happen to catch the messages before the controller jumps off the bus.
> I wonder which side initiates the key refresh. Also what is the remote
> device. You can try hcitool info <bdaddr> to get its features.
Ok. It might be a few days before I get time. Debian doesn't package this
so I'll need to build bluez from source, which I ought to do anyway for the
PS3 remote issues.
There is no remote device. As far as I am aware there is no bluetooth RF
activity whatsoever. Well, I did pair with my Android phone last week as a
test, but its bluetooth is currently switched off. The PS3 remote is also
in bluez' database, but it is also turned off (batteries removed).
> As I said before, just running bluemoon should decode the firmware version
> for you. No need to wildly guess.
Cool. Although I would like Ethan to clarify how the firmware files are
named, how he was able to deduce a version from my dmesg output, and whether
the new observation matches his expectation. There could be some issue
where the driver isn't loading the latest firmware on disk.
Mark
Hi Mark,
>>> So I tried this before going away for the weekend, rebooted, and then
>>> checked dmesg when I got back. The issue is still there, spontaneous
>>> disconnect/reconnect every 23h18m07s like clockwork.
>>
>> this sounds suspiciously like the validity of the encryption key. I assume
>> your connection is encrypted.
>
> Sorry, I should have re-iterated in the message, that this is a *USB*
> disconnect/reconnect. There is actually no bluetooth activity or
> connections at all during this time---bluetoothd is running, but that's it
> (although I am eager to test an IdleTimeout patch when it's available).
>
> I snipped the dmesg output from earlier in the thread; it looked like this:
>
> [83894.699185] usb 1-1: USB disconnect, device number 2
> [83894.914720] usb 1-1: new full-speed USB device number 3 using tegra-ehci
> [83895.044528] usb 1-1: New USB device found, idVendor=8087, idProduct=07dc
> [83895.051304] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
> [83895.076633] Bluetooth: hci0: read Intel version: 3707100180012d0d06
> [83895.082944] Bluetooth: hci0: Intel device is already patched. patch num: 06
> [167782.187624] usb 1-1: USB disconnect, device number 3
> [167782.403343] usb 1-1: new full-speed USB device number 4 using tegra-ehci
> [167782.532645] usb 1-1: New USB device found, idVendor=8087, idProduct=07dc
> [167782.539504] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
> [167782.564803] Bluetooth: hci0: read Intel version: 3707100180012d0d06
> [167782.571242] Bluetooth: hci0: Intel device is already patched. patch num: 06
> ...
>
> So, strictly a hardware driver/firmware issue of some kind. Either that, or
> something quite strange happening on my system which I've not figured out
> yet. (I do have other USB devices attached, which are not cycling like
> this.)
please run bluemoon -T to enable the LMP tracing feature and then see if you happen to catch the messages before the controller jumps off the bus. I wonder which side initiates the key refresh. Also what is the remote device. You can try hcitool info <bdaddr> to get its features.
As I said before, just running bluemoon should decode the firmware version for you. No need to wildly guess.
In general if the device gets kicked off the USB bus, then something bad happened. The firmware might has crashed or something like that. The fact that the interval is consistent and pretty much the validity period of the encryption key, I bet that something goes wrong with the key refresh procedure.
Regards
Marcel
Hi Marcel,
Marcel Holtmann [[email protected]] wrote:
> > So I tried this before going away for the weekend, rebooted, and then
> > checked dmesg when I got back. The issue is still there, spontaneous
> > disconnect/reconnect every 23h18m07s like clockwork.
>
> this sounds suspiciously like the validity of the encryption key. I assume
> your connection is encrypted.
Sorry, I should have re-iterated in the message, that this is a *USB*
disconnect/reconnect. There is actually no bluetooth activity or
connections at all during this time---bluetoothd is running, but that's it
(although I am eager to test an IdleTimeout patch when it's available).
I snipped the dmesg output from earlier in the thread; it looked like this:
[83894.699185] usb 1-1: USB disconnect, device number 2
[83894.914720] usb 1-1: new full-speed USB device number 3 using tegra-ehci
[83895.044528] usb 1-1: New USB device found, idVendor=8087, idProduct=07dc
[83895.051304] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[83895.076633] Bluetooth: hci0: read Intel version: 3707100180012d0d06
[83895.082944] Bluetooth: hci0: Intel device is already patched. patch num: 06
[167782.187624] usb 1-1: USB disconnect, device number 3
[167782.403343] usb 1-1: new full-speed USB device number 4 using tegra-ehci
[167782.532645] usb 1-1: New USB device found, idVendor=8087, idProduct=07dc
[167782.539504] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[167782.564803] Bluetooth: hci0: read Intel version: 3707100180012d0d06
[167782.571242] Bluetooth: hci0: Intel device is already patched. patch num: 06
...
So, strictly a hardware driver/firmware issue of some kind. Either that, or
something quite strange happening on my system which I've not figured out
yet. (I do have other USB devices attached, which are not cycling like
this.)
Mark
Hi Mark,
>> Your Intel FW version hci0: read Intel version: 3707100180012d0d06, it's
>> too old. Please try latest Intel WP2 FW
>> Ibt-hw-37.7.10-fw-1.80.1.2d.d.bseq in linux-firmware/intel.
>
> So I tried this before going away for the weekend, rebooted, and then
> checked dmesg when I got back. The issue is still there, spontaneous
> disconnect/reconnect every 23h18m07s like clockwork.
this sounds suspiciously like the validity of the encryption key. I assume your connection is encrypted.
Please provide the btmon output for the section where you see the disconnect + reconnect. I need to check what the firmware is telling us. And please include the initial connection setup as well. I need to see the features of the remote device.
However in theory the firmware should be using using encryption pause and resume to renew the encryption key prior to it expiring. We might need the LMP details in that case. You can use bluemoon -T to enable them (and that tool will also decode firmware version for you). Decoding the LMP vendor events will not be possible since we have not added support for it to btmon yet.
Regards
Marcel
Hi Ethan,
Ge, Ethan [[email protected]] wrote:
> Your Intel FW version hci0: read Intel version: 3707100180012d0d06, it's
> too old. Please try latest Intel WP2 FW
> Ibt-hw-37.7.10-fw-1.80.1.2d.d.bseq in linux-firmware/intel.
So I tried this before going away for the weekend, rebooted, and then
checked dmesg when I got back. The issue is still there, spontaneous
disconnect/reconnect every 23h18m07s like clockwork.
I am starting to second-guess myself a little, though, because I am confused
about the firmware naming. The firmware or microcode files I am familiar
with (iwlwifi for instance) have the firmware version as part of the file
name. The ibt-hw-* firmwares, on the other hand, appear to keep the *same*
filename when new versions come out; only the increased file size indicates
that the contents have changed. So I am guessing that the filename refers
to the hardware revision it is intended for, rather than the
firmware/microcode revision? Either that, or debian is not distributing the
same firmware files as the ones in git!
In any case, the dmesg output with the [presumed correct] firmware is
precisely the same as before:
Bluetooth: hci0: read Intel version: 3707100180012d0d06
Bluetooth: hci0: Intel device is already patched. patch num: 06
The size of the file "ibt-hw-37.7.10-fw-1.80.1.2d.d.bseq" is now 17310
bytes. That is larger than the one it overwrote, but I didn't write down
the old size.
Kernel version is 4.2.0-rc4.
Mark
Hi Mark,
Your Intel FW version hci0: read Intel version: 3707100180012d0d06, it's too old. Please try latest Intel WP2 FW Ibt-hw-37.7.10-fw-1.80.1.2d.d.bseq in linux-firmware/intel.
Ethan
-----Original Message-----
From: [email protected] [mailto:[email protected]] On Behalf Of Mark A. Haun
Sent: Thursday, August 20, 2015 1:21 PM
To: [email protected]
Subject: Intel 7260 spontaneous USB disconnect/reconnect every 23h18m07s
I have a late-model Intel 7260 wifi/bluetooth mini-PCIE card plugged into my Nvidia Jetson board. Bluetooth is basically working, but I've noticed the following odd pattern in my logs:
(previous 12 days omitted for brevity; pattern is same as below)
[...]
Aug 16 03:33:00 kolonia kernel: [921790.543197] usb 1-1: USB disconnect, device number 12 Aug 16 03:33:00 kolonia kernel: [921790.761151] usb 1-1: new full-speed USB device number 13 using tegra-ehci Aug 16 03:33:00 kolonia kernel: [921790.889599] usb 1-1: New USB device found, idVendor=8087, idProduct=07dc Aug 16 03:33:00 kolonia kernel: [921790.896428] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0 Aug 16 03:33:00 kolonia kernel: [921790.922681] Bluetooth: hci0: read Intel version: 3707100180012d0d06 Aug 16 03:33:00 kolonia kernel: [921790.929091] Bluetooth: hci0: Intel device is already patched. patch num: 06 Aug 16 03:33:00 kolonia bluetoothd[1888]: Sap driver initialization failed.
Aug 16 03:33:00 kolonia bluetoothd[1888]: sap-server: Operation not permitted (1) Aug 16 03:33:00 kolonia bluetoothd[1888]: Failed to set mode: Busy (0x0a)
[...]
Aug 18 02:09:13 kolonia kernel: [1089565.056222] usb 1-1: USB disconnect, device number 13 Aug 18 02:09:13 kolonia kernel: [1089565.271214] usb 1-1: new full-speed USB device number 14 using tegra-ehci Aug 18 02:09:13 kolonia kernel: [1089565.400011] usb 1-1: New USB device found, idVendor=8087, idProduct=07dc Aug 18 02:09:13 kolonia kernel: [1089565.406942] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0 Aug 18 02:09:13 kolonia kernel: [1089565.431982] Bluetooth: hci0: read Intel version: 3707100180012d0d06 Aug 18 02:09:13 kolonia kernel: [1089565.438483] Bluetooth: hci0: Intel device is already patched. patch num: 06 Aug 18 02:09:13 kolonia bluetoothd[1888]: Sap driver initialization failed.
Aug 18 02:09:13 kolonia bluetoothd[1888]: sap-server: Operation not permitted (1) Aug 18 02:09:13 kolonia bluetoothd[1888]: Failed to set mode: Busy (0x0a)
[...]
Aug 19 01:27:20 kolonia kernel: [1173452.517103] usb 1-1: USB disconnect, device number 14 Aug 19 01:27:20 kolonia kernel: [1173452.734122] usb 1-1: new full-speed USB device number 15 using tegra-ehci Aug 19 01:27:20 kolonia kernel: [1173452.865078] usb 1-1: New USB device found, idVendor=8087, idProduct=07dc Aug 19 01:27:20 kolonia kernel: [1173452.872018] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0 Aug 19 01:27:20 kolonia kernel: [1173452.899169] Bluetooth: hci0: read Intel version: 3707100180012d0d06 Aug 19 01:27:20 kolonia kernel: [1173452.905689] Bluetooth: hci0: Intel device is already patched. patch num: 06 Aug 19 01:27:20 kolonia bluetoothd[1888]: Sap driver initialization failed.
Aug 19 01:27:20 kolonia bluetoothd[1888]: sap-server: Operation not permitted (1) Aug 19 01:27:20 kolonia bluetoothd[1888]: Failed to set mode: Busy (0x0a)
The interval is very consistent at 23 hours, 18 minutes, and 7 seconds, plus or minus a second. This happens almost every day, but you can see it skipped August 17th for some reason. In that case the interval was exactly 2x, i.e.
the pattern continues.
Any idea why this would be happening? It doesn't seem to have any adverse effects, but I like a good mystery.