Re: Bluetooth connection disconnects every few minutes

[Julian Sikorski <belegdol@gmail.com>]

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@public.gmane.org> 
>>>>> 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
>>>>>
>>>>>
>>>>>
>>>>
>>>
>>>
>>
> 
>