Re: Bluetooth connection disconnects every few minutes

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



W dniu 21.12.2020 o 18:26, Julian Sikorski pisze:
W dniu 02.11.2020 o 20:40, Julian Sikorski pisze:
W dniu 05.09.2020 o 15:05, Julian Sikorski pisze:
W dniu 02.09.2020 o 07:58, Julian Sikorski pisze:
W dniu 02.09.2020 o 01:14, Luiz Augusto von Dentz pisze:
Hi Julian,

On Tue, Sep 1, 2020 at 1:42 PM Julian Sikorski <belegdol-Re5JQEeQqe8AvxtiuMwx3w-XMD5yJDbdMReXY1tMh2IBg-XMD5yJDbdMReXY1tMh2IBg@xxxxxxxxxxxxxxxx> wrote:

W dniu 01.09.2020 o 22:10, Julian Sikorski pisze:
W dniu 12.08.2018 o 17:49, Julian Sikorski pisze:
W dniu 01.08.2018 o 19:46, Julian Sikorski pisze:
W dniu 09.07.2018 o 18:51, Julian Sikorski pisze:
W dniu 08.07.2018 o 19:46, Georg Chini pisze:
On 08.07.2018 15:21, Julian Sikorski wrote:
W dniu 02.07.2018 o 20:09, Julian Sikorski pisze:
W dniu 02.07.2018 o 18:04, Georg Chini pisze:
On 02.07.2018 17:58, Julian Sikorski wrote:
W dniu 29.06.2018 o 21:47, Julian Sikorski pisze:
Hi list,

I have noticed that the bluetooth connection between my laptop (Intel 7260) and my headphones (Sennheiser Momentum Wirelless) is very unreliable. While under Windows 10 devices stay connected for
hours on
end, under Fedora 28 the connection is lost every few minutes at
most.
Often the connection will be reestablished only to be lost again.
bluetoothd shows messages like:


I am not sure where to look further. Does it look like an issue with pulseaudio, or a deeper problem with linux bluetooth stack? Thanks
for
your input in advance!

Best regards,
Julian
This is what is logged by pulseaudio at the time the connection is
lost:

( 118.064|  34.694) I: [bluetooth] module-bluez5-device.c: FD error:
POLLERR POLLHUP
( 118.064|   0.000) I: [bluetooth] bluez5-util.c: Transport
/org/bluez/hci0/dev_00_1B_66_81_8D_76/fd27 auto-released by BlueZ or
already released
( 118.064|   0.000) I: [pulseaudio] backend-native.c: Lost RFCOMM
connection.


  From what you are writing, it looks to me as if the issue is in the
USB
stack and the BT dongle keeps disconnecting/connecting. Have you
tried another dongle?
Hi,

I unfortunately do not own any other dongles. I tried getting some useful info with btmon but the log seems flooded with way too many
messages to make anything out.

Hi Georg,

it looks like the problem is more related to how the dongle interacts with this specific headphone model. I have recently bought another one for running (AfterShokz Trekz Air) and it works perfectly, connecting
automatically, staying connected and even switching profiles
automatically without issues so far.
The hci0: last event is not cmd complete (0x0f) message seems harmless as it spams the dmesg output regardless of the device connected (and
also when no device is connected at all.
It appears that whatever is happening it makes the dongle reconnect:

[nie lip  8 15:14:12 2018] usb 2-1.4: USB disconnect, device number 6 [nie lip  8 15:14:12 2018] usb 2-1.4: new full-speed USB device number 7
using ehci-pci
[nie lip  8 15:14:12 2018] usb 2-1.4: New USB device found,
idVendor=8087, idProduct=07dc, bcdDevice= 0.01
[nie lip  8 15:14:12 2018] usb 2-1.4: New USB device strings: Mfr=0,
Product=0, SerialNumber=0
[nie lip  8 15:14:12 2018] Bluetooth: hci0: read Intel version:
3707100180012d0d2a
[nie lip  8 15:14:12 2018] Bluetooth: hci0: Intel device is already
patched. patch num: 2a

Where would you recommend to look for reasons for this behaviour? btmon?
Thank you for the pointers!

Best regards,
Julian


Hi Julian,

sorry, I have no further ideas. Maybe Luiz can help you to investigate. To me it looks like the headphone is sending something that makes the
dongle reset.

Regards
             Georg

Hi Georg,

no worries - hopefully Luiz will find some time to look into this.
In the meantime I have been getting acquainted with btmon. I have
managed to pinpoint the exact moment during which sound stops coming through the headphones and starts coming through the laptop speakers. In
the below testcase, it happens at 18:42:58:

< ACL Data TX: Handle 256 flags 0x02 dlen 850
                               #1825 [hci0] 18:42:58.908586
       Channel: 450 len 846 [PSM 25 mode 0] {chan 2}
< ACL Data TX: Handle 256 flags 0x02 dlen 850
                               #1826 [hci0] 18:42:58.928877
       Channel: 450 len 846 [PSM 25 mode 0] {chan 2}
@ MGMT Event: Class Of Device Changed (0x0007) plen 3
                            {0x0002} [hci0] 18:43:00.653578
         Class: 0x000000
           Major class: Miscellaneous
           Minor class: 0x00
@ MGMT Event: Class Of Device Changed (0x0007) plen 3
                            {0x0001} [hci0] 18:43:00.653578
         Class: 0x000000
           Major class: Miscellaneous
           Minor class: 0x00
@ MGMT Event: New Settings (0x0006) plen 4
                            {0x0002} [hci0] 18:43:00.653609
         Current settings: 0x00000ada
           Connectable
           Discoverable
           Bondable
           Secure Simple Pairing
           BR/EDR
           Low Energy
           Secure Connections
@ MGMT Event: New Settings (0x0006) plen 4
                            {0x0001} [hci0] 18:43:00.653609
         Current settings: 0x00000ada
           Connectable
           Discoverable
           Bondable
           Secure Simple Pairing
           BR/EDR
           Low Energy
           Secure Connections
= bluetoothd: Unable to get io data for Headset Voice gateway:
getpeername: Transport endpoint is not connected.. 18:43:00.654133
= Close Index: 7C:5C:F8:B2:DF:08
                                     [hci0] 18:43:00.678348
@ MGMT Event: Index Removed (0x0005) plen 0
                            {0x0002} [hci0] 18:43:00.678372
@ MGMT Event: Index Removed (0x0005) plen 0
                            {0x0001} [hci0] 18:43:00.678372
= Delete Index: 7C:5C:F8:B2:DF:08
                                     [hci0] 18:43:00.678377
= bluetoothd: Endpoint unregistered: sender=:1.1492
path=/MediaEndpoint/A2DPSource
18:43:00.678966
= bluetoothd: Endpoint unregistered: sender=:1.1492
path=/MediaEndpoint/A2DPSink
18:43:00.678984

I am copying linux-bluetooth, maybe someone there will have an idea as
well. Thank you for all your help in advance!

Best regards,
Julian

Hi all,

I tried to get more information using hcidump, but it does not appear very interesting. I am attaching it here just in case. The last entry appearing - command complete (read encryption key size) - appears upon successful connection, not when the connection is dropped. How else
could I try to figure out what is being sent at the time of
disconnection? Thank you!

Best regards,
Julian

Hi list,

I just realised I never attached the full btmon dump. Here it goes, the
connection drops at 17:32:04:

< ACL Data TX: Handle 256 flags 0x02 dlen 850
                               #1340 [hci0] 17:32:04.774611
       Channel: 450 len 846 [PSM 25 mode 0] {chan 2}
HCI Event: Number of Completed Packets (0x13) plen 5
                               #1341 [hci0] 17:32:04.783175
         Num handles: 1
         Handle: 256
         Count: 1
< ACL Data TX: Handle 256 flags 0x02 dlen 850
                               #1342 [hci0] 17:32:04.794981
       Channel: 450 len 846 [PSM 25 mode 0] {chan 2}
HCI Event: Number of Completed Packets (0x13) plen 5
                               #1343 [hci0] 17:32:04.803054
         Num handles: 1
         Handle: 256
         Count: 1
< ACL Data TX: Handle 256 flags 0x02 dlen 850
                               #1344 [hci0] 17:32:04.815326
       Channel: 450 len 846 [PSM 25 mode 0] {chan 2}
HCI Event: Number of Completed Packets (0x13) plen 5
                               #1345 [hci0] 17:32:04.823198
         Num handles: 1
         Handle: 256
         Count: 1
< ACL Data TX: Handle 256 flags 0x02 dlen 850
                               #1346 [hci0] 17:32:04.835578
       Channel: 450 len 846 [PSM 25 mode 0] {chan 2}
< ACL Data TX: Handle 256 flags 0x02 dlen 850
                               #1347 [hci0] 17:32:04.856093
       Channel: 450 len 846 [PSM 25 mode 0] {chan 2}
< ACL Data TX: Handle 256 flags 0x02 dlen 850
                               #1348 [hci0] 17:32:04.876186
       Channel: 450 len 846 [PSM 25 mode 0] {chan 2}
< ACL Data TX: Handle 256 flags 0x02 dlen 850
                               #1349 [hci0] 17:32:04.896454
       Channel: 450 len 846 [PSM 25 mode 0] {chan 2}
< ACL Data TX: Handle 256 flags 0x02 dlen 850
                               #1350 [hci0] 17:32:04.916869
       Channel: 450 len 846 [PSM 25 mode 0] {chan 2}
@ MGMT Event: Class Of Device Changed (0x0007) plen 3
                            {0x0002} [hci0] 17:32:06.637019
         Class: 0x000000
           Major class: Miscellaneous
           Minor class: 0x00
@ MGMT Event: Class Of Device Changed (0x0007) plen 3
                            {0x0001} [hci0] 17:32:06.637019
         Class: 0x000000
           Major class: Miscellaneous
           Minor class: 0x00
@ MGMT Event: New Settings (0x0006) plen 4
                            {0x0002} [hci0] 17:32:06.637034
         Current settings: 0x00000ada
           Connectable
           Discoverable
           Bondable
           Secure Simple Pairing
           BR/EDR
           Low Energy
           Secure Connections
@ MGMT Event: New Settings (0x0006) plen 4
                            {0x0001} [hci0] 17:32:06.637034
         Current settings: 0x00000ada
           Connectable
           Discoverable
           Bondable
           Secure Simple Pairing
           BR/EDR
           Low Energy
           Secure Connections
= Close Index: 7C:5C:F8:B2:DF:08
                                     [hci0] 17:32:06.654087
@ MGMT Event: Index Removed (0x0005) plen 0
                            {0x0002} [hci0] 17:32:06.654114
@ MGMT Event: Index Removed (0x0005) plen 0
                            {0x0001} [hci0] 17:32:06.654114
= Delete Index: 7C:5C:F8:B2:DF:08
                                     [hci0] 17:32:06.654120
= bluetoothd: Unable to get io data for Headset Voice gateway:
getpeername: Transport endpoint is not connected.. 17:32:06.654352
= bluetoothd: Endpoint unregistered: sender=:1.750
path=/MediaEndpoint/A2DPSource
17:32:06.654796
= bluetoothd: Endpoint unregistered: sender=:1.750
path=/MediaEndpoint/A2DPSink
17:32:06.654836

I tried sending the btmon capture as attachment but it appears to be too
large for the list, so I uploaded it here instead:

https://belegdol.fedorapeople.org/btmon-aug.log

Is this perhaps related to https://github.com/bluez/bluez/issues/18,
we have a fix already applied upstream for it.


Hi Luiz,

it looks like a different issue. I tried both passing --noplugin=avrcp
and applying the two patches mentioned in the github issue to Fedora
RPM, neither helped. I am attaching a new btmon capture in case
something changed. In this one the disconnect happens after #371.

Best regards,
Julian
Hi Luiz,

I have now tested the same headset (Sennheiser Momentum Wireless aka M2 AEBT) with another machine, this time a desktop equipped with Intel 3168NGW dongle. With this machine everything appears to be working flawlessly, with no disconnection happening for several minutes. I have uploaded the btmon log to my dropbox as it is too large to attach here:
https://www.dropbox.com/s/ttetss50jqlvi35/m2-aebt-desktop.zip?dl=0
Hopefully there is something in the log indicating as to why the headset keeps disconnecting from the laptop. The laptop is equipped with Intel 7260 dongle.

Best regards,
Julian


The problem is still happening with kernel-5.8.17, bluez-5.55 and Fedora 33. Latest log is attached, the disconnect happens after #1023. I tried deleting ~/.config/pulse as a hail mary attempt, but it did not help either.

Best regards,
Julian

It is still broken with kernel-5.9.15. The strange thing is that every now and again if the stars align just right, the connection is stable. Is there a way of making btmon even more verbose so that I can see what is going on? My wild guess is that the stability of the connection has something to do with which profile (A2DP or HSP) gets activated first. Can this be controlled somehow?

Best regards,
Julian

This could be just an impression, but it appears that the A2DP connection can be rendered stable if I quickly switch PA to HSP/HFP and back to A2DP after the initial connection before the connection is dropped. btmon capture of this attempt (it is too big to attach here):
https://www.dropbox.com/s/ozi0q1ucb32eovd/btmon-working.log?dl=0.

Best regards,
Julian
Best regards,
Julian


Hi all,

I have tried the headset again with kernel-5.8.4, bluez-5.54 and
pulseaudio-13.99.1. The situation has unfortunately not improved in the
last two years.
I am attaching the btmon capture of two connection attempts:
- the first connects and then almost immediately disconnects
- the second never succeeds
Does the capture provide any information as to why the connection is
failing? If I can provide any more data, please let me know. Thanks!

Best regards,
Julian

If I am not mistaken, the disconnect happens right after #636

Best regards,
Julian















[Index of Archives]     [Bluez Devel]     [Linux Wireless Networking]     [Linux Wireless Personal Area Networking]     [Linux ATH6KL]     [Linux USB Devel]     [Linux Media Drivers]     [Linux Audio Users]     [Linux Kernel]     [Linux SCSI]     [Big List of Linux Books]

  Powered by Linux