[pulseaudio-discuss] Bluetooth connection disconnects every few minutes

Post by Julian Sikorski
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.
sender=:1.145 path=/MediaEndpoint/A2DPSource
sender=:1.145 path=/MediaEndpoint/A2DPSink
sender=:1.145 path=/MediaEndpoint/A2DPSource
sender=:1.145 path=/MediaEndpoint/A2DPSink
/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)
sender=:1.145 path=/MediaEndpoint/A2DPSource
sender=:1.145 path=/MediaEndpoint/A2DPSink
sender=:1.145 path=/MediaEndpoint/A2DPSource
sender=:1.145 path=/MediaEndpoint/A2DPSink
/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)
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
Mfr=0, Product=0, SerialNumber=0
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
Mfr=0, Product=0, SerialNumber=0
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
Mfr=0, Product=0, SerialNumber=0
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.

Georg Chini

2018-07-02 16:04:43 UTC

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?

Julian Sikorski

2018-07-02 18:09:31 UTC

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.

Julian Sikorski

2018-07-08 13:21:20 UTC

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

Georg Chini

2018-07-08 17:46:25 UTC

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

Julian Sikorski

2018-07-09 16:51:16 UTC

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

Julian Sikorski

2018-08-01 17:46:26 UTC

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

Julian Sikorski

2018-08-12 15:49:18 UTC