[pulseaudio-discuss] Bluetooth connection disconnects every few minutes

Sun Jul 8 13:21:20 UTC 2018

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:
>>>>
>>>> cze 29 21:31:13 snowball2 bluetoothd[3832]: Endpoint unregistered:
>>>> sender=:1.145 path=/MediaEndpoint/A2DPSource
>>>> cze 29 21:31:13 snowball2 bluetoothd[3832]: Endpoint unregistered:
>>>> sender=:1.145 path=/MediaEndpoint/A2DPSink
>>>> cze 29 21:31:13 snowball2 bluetoothd[3832]: Endpoint registered:
>>>> sender=:1.145 path=/MediaEndpoint/A2DPSource
>>>> cze 29 21:31:13 snowball2 bluetoothd[3832]: Endpoint registered:
>>>> sender=:1.145 path=/MediaEndpoint/A2DPSink
>>>> cze 29 21:31:39 snowball2 bluetoothd[3832]:
>>>> /org/bluez/hci0/dev_00_1B_66_81_8D_76/fd5: fd(25) ready
>>>> cze 29 21:33:02 snowball2 bluetoothd[3832]: Unable to get io data for
>>>> Headset Voice gateway: getpeername: Transport endpoint is not connected
>>>> (107)
>>>> cze 29 21:33:02 snowball2 bluetoothd[3832]: Endpoint unregistered:
>>>> sender=:1.145 path=/MediaEndpoint/A2DPSource
>>>> cze 29 21:33:02 snowball2 bluetoothd[3832]: Endpoint unregistered:
>>>> sender=:1.145 path=/MediaEndpoint/A2DPSink
>>>> cze 29 21:33:03 snowball2 bluetoothd[3832]: Endpoint registered:
>>>> sender=:1.145 path=/MediaEndpoint/A2DPSource
>>>> cze 29 21:33:03 snowball2 bluetoothd[3832]: Endpoint registered:
>>>> sender=:1.145 path=/MediaEndpoint/A2DPSink
>>>> cze 29 21:33:31 snowball2 bluetoothd[3832]:
>>>> /org/bluez/hci0/dev_00_1B_66_81_8D_76/fd6: fd(25) ready
>>>> cze 29 21:35:38 snowball2 bluetoothd[3832]: Unable to get io data for
>>>> Headset Voice gateway: getpeername: Transport endpoint is not connected
>>>> (107)
>>>>
>>>> dmesg for the same period looks as follows:
>>>>
>>>> 2018-06-29T21:30:58,743292+02:00 Bluetooth: hci0: last event is not cmd
>>>> complete (0x0f)
>>>> 2018-06-29T21:31:12,613199+02:00 usb 2-1.4: USB disconnect, device
>>>> number 8
>>>> 2018-06-29T21:31:12,809196+02:00 usb 2-1.4: new full-speed USB device
>>>> number 9 using ehci-pci
>>>> 2018-06-29T21:31:12,889200+02:00 usb 2-1.4: New USB device found,
>>>> idVendor=8087, idProduct=07dc, bcdDevice= 0.01
>>>> 2018-06-29T21:31:12,889203+02:00 usb 2-1.4: New USB device strings:
>>>> Mfr=0, Product=0, SerialNumber=0
>>>> 2018-06-29T21:31:12,903435+02:00 Bluetooth: hci0: read Intel version:
>>>> 3707100180012d0d2a
>>>> 2018-06-29T21:31:12,903438+02:00 Bluetooth: hci0: Intel device is
>>>> already patched. patch num: 2a
>>>> 2018-06-29T21:31:13,002369+02:00 Bluetooth: hci0: last event is not cmd
>>>> complete (0x0f)
>>>> 2018-06-29T21:31:28,853543+02:00 Bluetooth: hci0: last event is not cmd
>>>> complete (0x0f)
>>>> 2018-06-29T21:31:39,625447+02:00 input: 00:1B:66:81:8D:76 as
>>>> /devices/virtual/input/input31
>>>> 2018-06-29T21:31:44,742251+02:00 Bluetooth: hci0: last event is not cmd
>>>> complete (0x0f)
>>>> 2018-06-29T21:32:00,746866+02:00 Bluetooth: hci0: last event is not cmd
>>>> complete (0x0f)
>>>> 2018-06-29T21:32:16,747075+02:00 Bluetooth: hci0: last event is not cmd
>>>> complete (0x0f)
>>>> 2018-06-29T21:32:32,746099+02:00 Bluetooth: hci0: last event is not cmd
>>>> complete (0x0f)
>>>> 2018-06-29T21:32:48,747212+02:00 Bluetooth: hci0: last event is not cmd
>>>> complete (0x0f)
>>>> 2018-06-29T21:33:02,403071+02:00 usb 2-1.4: USB disconnect, device
>>>> number 9
>>>> 2018-06-29T21:33:02,595275+02:00 usb 2-1.4: new full-speed USB device
>>>> number 10 using ehci-pci
>>>> 2018-06-29T21:33:02,675493+02:00 usb 2-1.4: New USB device found,
>>>> idVendor=8087, idProduct=07dc, bcdDevice= 0.01
>>>> 2018-06-29T21:33:02,675502+02:00 usb 2-1.4: New USB device strings:
>>>> Mfr=0, Product=0, SerialNumber=0
>>>> 2018-06-29T21:33:02,691213+02:00 Bluetooth: hci0: read Intel version:
>>>> 3707100180012d0d2a
>>>> 2018-06-29T21:33:02,691216+02:00 Bluetooth: hci0: Intel device is
>>>> already patched. patch num: 2a
>>>> 2018-06-29T21:33:02,791228+02:00 Bluetooth: hci0: last event is not cmd
>>>> complete (0x0f)
>>>> 2018-06-29T21:33:18,854324+02:00 Bluetooth: hci0: last event is not cmd
>>>> complete (0x0f)
>>>> 2018-06-29T21:33:31,481782+02:00 input: 00:1B:66:81:8D:76 as
>>>> /devices/virtual/input/input32
>>>> 2018-06-29T21:33:34,742175+02:00 Bluetooth: hci0: last event is not cmd
>>>> complete (0x0f)
>>>> 2018-06-29T21:35:37,864703+02:00 usb 2-1.4: USB disconnect, device
>>>> number 10
>>>> 2018-06-29T21:35:38,056428+02:00 usb 2-1.4: new full-speed USB device
>>>> number 11 using ehci-pci
>>>> 2018-06-29T21:35:38,140706+02:00 usb 2-1.4: New USB device found,
>>>> idVendor=8087, idProduct=07dc, bcdDevice= 0.01
>>>> 2018-06-29T21:35:38,140712+02:00 usb 2-1.4: New USB device strings:
>>>> Mfr=0, Product=0, SerialNumber=0
>>>> 2018-06-29T21:35:38,155840+02:00 Bluetooth: hci0: read Intel version:
>>>> 3707100180012d0d2a
>>>> 2018-06-29T21:35:38,155843+02:00 Bluetooth: hci0: Intel device is
>>>> already patched. patch num: 2a
>>>>
>>>> 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