search

bluez / bluez

Main BlueZ tree
https://bluez.github.io/bluez/
GNU General Public License v2.0
737 stars 272 forks source link

Wireless Ear Buds get randomly disconnected. #419

Closed K4R7IK closed 1 year ago

K4R7IK commented 1 year ago

Basic problem is that my wireless buds get randomly disconnect and then sometime reconnects and sometimes not. This problem doesn't occur with my Bluetooth Speaker. It only happens when I connect my buds to my laptop.

sudo journalctl -b -u bluetooth.service gives the following.

Oct 30 19:16:09 Rot bluetoothd[578]: /org/bluez/hci0/dev_FC_58_FA_32_0C_D4/sep1/fd6: fd(30) ready
Oct 30 19:16:36 Rot bluetoothd[578]: /org/bluez/hci0/dev_D8_6C_02_50_B0_1B/fd7: fd(34) ready
Oct 30 19:20:15 Rot bluetoothd[578]: src/profile.c:ext_io_disconnected() Unable to get io data for Hands-Free Voice gateway: getpeername: Transport endpoint is not connected (107)
Oct 30 19:20:16 Rot bluetoothd[578]: src/service.c:btd_service_connect() a2dp-sink profile connect failed for D8:6C:02:50:B0:1B: Device or resource busy
Oct 30 19:20:16 Rot bluetoothd[578]: plugins/policy.c:reconnect_timeout() Reconnecting services failed: Device or resource busy (16)
Oct 30 19:20:18 Rot bluetoothd[578]: /org/bluez/hci0/dev_D8_6C_02_50_B0_1B/fd8: fd(29) ready
Oct 30 19:25:26 Rot bluetoothd[578]: src/profile.c:ext_io_disconnected() Unable to get io data for Hands-Free Voice gateway: getpeername: Transport endpoint is not connected (107)
Oct 30 19:25:28 Rot bluetoothd[578]: src/service.c:btd_service_connect() a2dp-sink profile connect failed for D8:6C:02:50:B0:1B: Device or resource busy
Oct 30 19:25:28 Rot bluetoothd[578]: plugins/policy.c:reconnect_timeout() Reconnecting services failed: Device or resource busy (16)
Oct 30 19:25:29 Rot bluetoothd[578]: /org/bluez/hci0/dev_D8_6C_02_50_B0_1B/fd9: fd(29) ready

Search online but didn't find any useful information or help for my case.

If you need any other information, please let me know. Thanks.

Vudentz commented 1 year ago

@Corrupter-rot please add the HCI traces, you can collect it using btmon.

K4R7IK commented 1 year ago

Sometime it happens rarely and something every other minute. So it hard for me to catch the random disconnect in the Bluetooth.

Here is log file of when earbuds were connected and no audio was playing. hcihump.log

But the random disconnect didn't occur during this time.

K4R7IK commented 1 year ago

I was able to catch the random disconnect. Here is the log file for that. hcihump2.log

Vudentz commented 1 year ago 
> HCI Event: Mode Change (0x14) plen 6                                                                                                                                                                                                                               #19091 [hci0] 231.755604
        Status: Success (0x00)
        Handle: 2
        Mode: Sniff (0x02)
        Interval: 500.000 msec (0x0320)
> HCI Event: Disconnect Complete (0x05) plen 4                                                                                                                                                                                                                       #19092 [hci0] 253.639344
        Status: Success (0x00)
        Handle: 2
        Reason: Connection Timeout (0x08)

So this is down in the link layer, apparently the device is entering sniff mode and then the connection times out, so probably the controller could not get acks for some reason which ends up causing the connection to time out.

K4R7IK commented 1 year ago

Any reason why it does that?

h3nill commented 1 year ago

facing the same issue, any way i can help debug this further?

could it be similar issue to https://github.com/bluez/bluez/issues/130?

I am using Realtek MT7922. @Corrupter-rot what wireless card are you using?

I get couple different but similar kinds of error from journalctl:

Feb 11 17:15:17 henil bluetoothd[596]: profiles/audio/avdtp.c:cancel_request() Suspend: Connection timed out (110)
Feb 11 17:15:18 henil bluetoothd[596]: src/profile.c:ext_io_disconnected() Unable to get io data for Hands-Free Voice gateway: getpeername: Transport endpoint is not connected (107)
Feb 11 17:15:18 henil bluetoothd[596]: profiles/audio/avdtp.c:handle_unanswered_req() No reply to Suspend request
Feb 11 17:15:19 henil bluetoothd[596]: src/service.c:btd_service_connect() a2dp-sink profile connect failed for 74:D7:13:00:9F:95: Device or resource busy
Feb 11 17:15:19 henil bluetoothd[596]: plugins/policy.c:reconnect_timeout() Reconnecting services failed: Device or resource busy (16)
Feb 11 17:15:25 bubble bluetoothd[596]: /org/bluez/hci0/dev_74_D7_13_00_9F_95/fd5: fd(40) ready 
Feb 11 17:21:49 henil bluetoothd[596]: profiles/audio/avdtp.c:cancel_request() Suspend: Connection timed out (110)
Feb 11 17:21:51 henil bluetoothd[596]: profiles/audio/avdtp.c:handle_unanswered_req() No reply to Suspend request
Feb 11 17:21:51 henil bluetoothd[596]: src/profile.c:ext_io_disconnected() Unable to get io data for Hands-Free Voice gateway: getpeername: Transport endpoint
is not connected (107)
Feb 11 17:22:20 henil bluetoothd[596]: /org/bluez/hci0/dev_74_D7_13_00_9F_95/sep2/fd6: fd(42) ready
Feb 11 17:39:37 henil bluetoothd[596]: src/profile.c:ext_io_disconnected() Unable to get io data for Hands-Free Voice gateway: getpeername: Transport endpoint>
Whimfoome commented 1 year ago

Facing the same problem.

Logs from journalctl | grep -i “blue*”:

окт 30 14:10:41 fedora bluetoothd[782]: profiles/audio/avdtp.c:cancel_request() Suspend: Connection timed out (110)
окт 30 14:10:42 fedora bluetoothd[782]: profiles/audio/avdtp.c:handle_unanswered_req() No reply to Suspend request
окт 30 14:10:42 fedora bluetoothd[782]: src/profile.c:ext_io_disconnected() Unable to get io data for Hands-Free Voice gateway: getpeername: Transport endpoint is not connected (107)
окт 30 14:10:44 fedora bluetoothd[782]: plugins/policy.c:reconnect_timeout() Reconnecting services failed: Operation already in progress (114)

Another thing to point out, it happens on Arch and Fedora, but it doesn't occur on Ubuntu. Also it doesn't seem to be due to the Bluetooth adapter, because I tried with multiple ones.

h3nill commented 1 year ago

might be related to this bug:

recently when i using buds some state got messed up and bluetooth started disconnecting very frequently and wasn't able to play any audio.

So to reduce surface area to debug, I:

So looks like some temporary state got corrupted, which isn't able to fix itself by restarting bluetooth related services.

h3nill commented 1 year ago

After restart (with Dual-device connection disabled and buds connected to laptop only), I got a disconnection exactly 5 minute after the connection.

See 16:13:47 -> 16:18:47

journalctl -xe -u bluetooth ``` Feb 21 16:12:30 henil systemd[1]: Starting Bluetooth service... ░░ Subject: A start job for unit bluetooth.service has begun execution ░░ Defined-By: systemd ░░ Support: https://lists.freedesktop.org/mailman/listinfo/systemd-devel ░░ ░░ A start job for unit bluetooth.service has begun execution. ░░ ░░ The job identifier is 159. Feb 21 16:12:30 henil bluetoothd[592]: Bluetooth daemon 5.66 Feb 21 16:12:30 henil bluetoothd[592]: Starting SDP server Feb 21 16:12:30 henil bluetoothd[592]: profiles/audio/vcp.c:vcp_init() D-Bus experimental not enabled Feb 21 16:12:30 henil bluetoothd[592]: src/plugin.c:plugin_init() Failed to init vcp plugin Feb 21 16:12:30 henil bluetoothd[592]: profiles/audio/mcp.c:mcp_init() D-Bus experimental not enabled Feb 21 16:12:30 henil bluetoothd[592]: src/plugin.c:plugin_init() Failed to init mcp plugin Feb 21 16:12:30 henil bluetoothd[592]: profiles/audio/bap.c:bap_init() D-Bus experimental not enabled Feb 21 16:12:30 henil bluetoothd[592]: src/plugin.c:plugin_init() Failed to init bap plugin Feb 21 16:12:30 henil systemd[1]: Started Bluetooth service. ░░ Subject: A start job for unit bluetooth.service has finished successfully ░░ Defined-By: systemd ░░ Support: https://lists.freedesktop.org/mailman/listinfo/systemd-devel ░░ ░░ A start job for unit bluetooth.service has finished successfully. ░░ ░░ The job identifier is 159. Feb 21 16:12:30 henil bluetoothd[592]: Bluetooth management interface 1.22 initialized Feb 21 16:12:37 henil bluetoothd[592]: Endpoint registered: sender=:1.31 path=/MediaEndpoint/A2DPSink/aac Feb 21 16:12:37 henil bluetoothd[592]: Endpoint registered: sender=:1.31 path=/MediaEndpoint/A2DPSource/aac Feb 21 16:13:47 henil bluetoothd[592]: /org/bluez/hci0/dev_74_D7_13_00_72_5C/sep2/fd0: fd(41) ready Feb 21 16:18:47 henil bluetoothd[592]: src/profile.c:ext_io_disconnected() Unable to get io data for Hands-Free Voice gateway: getpeername: Transport endpoint> Feb 21 16:18:49 henil bluetoothd[592]: src/service.c:btd_service_connect() a2dp-sink profile connect failed for 74:D7:13:00:72:5C: Device or resource busy Feb 21 16:18:49 henil bluetoothd[592]: plugins/policy.c:reconnect_timeout() Reconnecting services failed: Device or resource busy (16) Feb 21 16:18:50 henil bluetoothd[592]: /org/bluez/hci0/dev_74_D7_13_00_72_5C/fd1: fd(40) ready ```

Here is HCI traces of that time.

I don't understand HCI protocol but from my initial look at logs unlike @Corrupter-rot's case doesn't look like disconnection was due to device going in Sniff mode. Any ideas @Vudentz ?

EDIT1: 1 hour after the initial disconnection and its still working fine.

EDIT2: Well spoke too soon,

journalctl -xe -u bluetooth ``` Feb 21 16:18:50 henil bluetoothd[592]: /org/bluez/hci0/dev_74_D7_13_00_72_5C/fd1: fd(40) ready Feb 21 17:35:07 henil bluetoothd[592]: src/profile.c:ext_io_disconnected() Unable to get io data for Hands-Free Voice gateway: getpeername: Transport endpoint> Feb 21 17:35:08 henil bluetoothd[592]: src/service.c:btd_service_connect() a2dp-sink profile connect failed for 74:D7:13:00:72:5C: Device or resource busy Feb 21 17:35:08 henil bluetoothd[592]: plugins/policy.c:reconnect_timeout() Reconnecting services failed: Device or resource busy (16) ```
K4R7IK commented 1 year ago

@henil I think my bluetooth and wireless card are integrated in one, therefore the card is Realtek RTL8822CE. Also I think the problem doesn't occur when using Pulseaudio. It only happens when using Pipewire.

h3nill commented 1 year ago

@henil I think my bluetooth and wireless card are integrated in one, therefore the card is Realtek RTL8822CE. Also I think the problem doesn't occur when using Pulseaudio. It only happens when using Pipewire.

My bluetooth and wireless card are integrated as well, I am on Realtek MT7922. Don't think that effects much.

I will try using pulseaudio instead of pipewire and report back.

pv commented 1 year ago

I will try using pulseaudio instead of pipewire and report back.

Make sure to use the same audio codec in the comparisons (pulseaudio does not have AAC), in case it depends on that.

h3nill commented 1 year ago

I tried to switch from pipewire to pulseaudio on my machine but it was breaking a lot of other things so i couldn't test it properly.

And I switched back to pipewire (with wireplumber), I tried using SBC bluetooth codec but still experienced disconnects, although with a different error message this time (see around timestamp 17:42).

journalctl -xe -u bluetooth ``` ░░ The job identifier is 159. Mar 03 15:10:03 henil bluetoothd[519]: Bluetooth daemon 5.66 Mar 03 15:10:03 henil bluetoothd[519]: Starting SDP server Mar 03 15:10:03 henil bluetoothd[519]: profiles/audio/vcp.c:vcp_init() D-Bus experimental not enabled Mar 03 15:10:03 henil bluetoothd[519]: src/plugin.c:plugin_init() Failed to init vcp plugin Mar 03 15:10:03 henil bluetoothd[519]: profiles/audio/mcp.c:mcp_init() D-Bus experimental not enabled Mar 03 15:10:03 henil bluetoothd[519]: src/plugin.c:plugin_init() Failed to init mcp plugin Mar 03 15:10:03 henil bluetoothd[519]: profiles/audio/bap.c:bap_init() D-Bus experimental not enabled Mar 03 15:10:03 henil bluetoothd[519]: src/plugin.c:plugin_init() Failed to init bap plugin Mar 03 15:10:03 henil systemd[1]: Started Bluetooth service. ░░ Subject: A start job for unit bluetooth.service has finished successfully ░░ Defined-By: systemd ░░ Support: https://lists.freedesktop.org/mailman/listinfo/systemd-devel ░░ ░░ A start job for unit bluetooth.service has finished successfully. ░░ ░░ The job identifier is 159. Mar 03 15:10:03 henil bluetoothd[519]: Bluetooth management interface 1.22 initialized Mar 03 15:10:13 henil bluetoothd[519]: Endpoint registered: sender=:1.31 path=/MediaEndpoint/A2DPSource/ldac Mar 03 15:10:13 henil bluetoothd[519]: Endpoint registered: sender=:1.31 path=/MediaEndpoint/A2DPSink/aptx_hd Mar 03 15:10:13 henil bluetoothd[519]: Endpoint registered: sender=:1.31 path=/MediaEndpoint/A2DPSource/aptx_hd Mar 03 15:10:13 henil bluetoothd[519]: Endpoint registered: sender=:1.31 path=/MediaEndpoint/A2DPSink/aptx Mar 03 15:10:13 henil bluetoothd[519]: Endpoint registered: sender=:1.31 path=/MediaEndpoint/A2DPSource/aptx Mar 03 15:10:13 henil bluetoothd[519]: Endpoint registered: sender=:1.31 path=/MediaEndpoint/A2DPSink/aac Mar 03 15:10:13 henil bluetoothd[519]: Endpoint registered: sender=:1.31 path=/MediaEndpoint/A2DPSource/aac Mar 03 15:10:13 henil bluetoothd[519]: Endpoint registered: sender=:1.31 path=/MediaEndpoint/A2DPSink/sbc Mar 03 15:10:13 henil bluetoothd[519]: Endpoint registered: sender=:1.31 path=/MediaEndpoint/A2DPSource/sbc Mar 03 15:10:13 henil bluetoothd[519]: Endpoint registered: sender=:1.31 path=/MediaEndpoint/A2DPSink/sbc_xq Mar 03 15:10:13 henil bluetoothd[519]: Endpoint registered: sender=:1.31 path=/MediaEndpoint/A2DPSource/sbc_xq Mar 03 15:10:13 henil bluetoothd[519]: Endpoint registered: sender=:1.31 path=/MediaEndpoint/A2DPSource/aptx_ll_1 Mar 03 15:10:13 henil bluetoothd[519]: Endpoint registered: sender=:1.31 path=/MediaEndpoint/A2DPSource/aptx_ll_0 Mar 03 15:10:13 henil bluetoothd[519]: Endpoint registered: sender=:1.31 path=/MediaEndpoint/A2DPSource/aptx_ll_duplex_1 Mar 03 15:10:13 henil bluetoothd[519]: Endpoint registered: sender=:1.31 path=/MediaEndpoint/A2DPSource/aptx_ll_duplex_0 Mar 03 15:10:13 henil bluetoothd[519]: Endpoint registered: sender=:1.31 path=/MediaEndpoint/A2DPSource/faststream Mar 03 15:10:13 henil bluetoothd[519]: Endpoint registered: sender=:1.31 path=/MediaEndpoint/A2DPSource/faststream_duplex Mar 03 15:10:13 henil bluetoothd[519]: Endpoint registered: sender=:1.31 path=/MediaEndpoint/A2DPSink/opus_05 Mar 03 15:10:13 henil bluetoothd[519]: Endpoint registered: sender=:1.31 path=/MediaEndpoint/A2DPSource/opus_05 Mar 03 15:10:13 henil bluetoothd[519]: Endpoint registered: sender=:1.31 path=/MediaEndpoint/A2DPSink/opus_05_duplex Mar 03 15:10:13 henil bluetoothd[519]: Endpoint registered: sender=:1.31 path=/MediaEndpoint/A2DPSource/opus_05_duplex Mar 03 15:10:17 henil bluetoothd[519]: src/adv_monitor.c:btd_adv_monitor_power_down() Unexpected NULL btd_adv_monitor_manager object upon power down Mar 03 17:23:11 henil bluetoothd[519]: /org/bluez/hci0/dev_74_D7_13_00_72_5C/sep1/fd0: fd(41) ready Mar 03 17:42:16 henil bluetoothd[519]: profiles/audio/avdtp.c:handle_unanswered_req() No reply to Close request Mar 03 17:42:24 henil bluetoothd[519]: /org/bluez/hci0/dev_74_D7_13_00_72_5C/sep1/fd2: fd(40) ready ```
Here is dmesg incase this helps ``` [ 5.122948] Bluetooth: Core ver 2.22 [ 5.122970] NET: Registered PF_BLUETOOTH protocol family [ 5.122971] Bluetooth: HCI device and connection manager initialized [ 5.122977] Bluetooth: HCI socket layer initialized [ 5.122979] Bluetooth: L2CAP socket layer initialized [ 5.122982] Bluetooth: SCO socket layer initialized [ 5.574404] Bluetooth: BNEP (Ethernet Emulation) ver 1.3 [ 5.574408] Bluetooth: BNEP filters: protocol multicast [ 5.574411] Bluetooth: BNEP socket layer initialized [ 7.532959] Bluetooth: hci0: Device setup in 2226749 usecs [ 7.532969] Bluetooth: hci0: HCI Enhanced Setup Synchronous Connection command is advertised, but not supported. [ 7.591637] Bluetooth: hci0: AOSP extensions version v1.00 [ 7.591646] Bluetooth: hci0: AOSP quality report is supported [ 7.591897] Bluetooth: MGMT ver 1.22 [ 15.355895] Bluetooth: RFCOMM TTY layer initialized [ 15.355911] Bluetooth: RFCOMM socket layer initialized [ 15.355917] Bluetooth: RFCOMM ver 1.11 [ 7981.899422] Bluetooth: hci0: Device setup in 141841 usecs [ 7981.899435] Bluetooth: hci0: HCI Enhanced Setup Synchronous Connection command is advertised, but not supported. [ 7981.981555] Bluetooth: hci0: AOSP extensions version v1.00 [ 7981.981562] Bluetooth: hci0: AOSP quality report is supported [ 8316.486833] Bluetooth: hci0: ACL packet for unknown connection handle 3837 [ 9122.017476] Bluetooth: hci0: ACL packet for unknown connection handle 3837 ```

Anyone else able to use it properly on pulseaudio and not on pipewire?

MASHtm commented 1 year ago

I can add Fedora 37 bluez-5.66-4.fc37.x86_64 Lenovo Carbon X1 G9 (latest bios/firmware) with Intel AX201 Earfun Free Pro to the list.

Using pipewire and AAC profile. Doesn't matter if I use Audacious, VLC, ... happens after about 30-45 Minutes. LowLatency mode (used with VLC) of the earbuds doesn't change disconnects.

The earbuds respond with audible "power on", "pairing" and "connected" messages. So it seems they get some kind of "power off" or "reset" command.

journal shows

bluetoothd[272168]: profiles/audio/avdtp.c:handle_unanswered_req() No reply to Suspend request
wireplumber[4391]: Failed to release transport /org/bluez/hci0/dev_B0_F1_A3_XX_XX_XX/sep2/fd0: Input/output error
bluetoothd[272168]: src/profile.c:ext_io_disconnected() Unable to get io data for Hands-Free Voice gateway: getpeername: Transport endpoint is not connected (107)
bluetoothd[272168]: src/profile.c:record_cb() Unable to get Hands-Free Voice gateway SDP record: Host is down
bluetoothd[272168]: plugins/policy.c:reconnect_timeout() Reconnecting services failed: Device or resource busy (16)
kernel: input: EarFun Free Pro (AVRCP) as /devices/virtual/input/input32
systemd-logind[1627]: Watching system buttons on /dev/input/event18 (EarFun Free Pro (AVRCP))
bluetoothd[272168]: /org/bluez/hci0/dev_B0_F1_A3_XX_XX_XX/sep2/fd1: fd(43) ready

Will try to capture btmon logs as well.

h3nill commented 1 year ago

I tried to switch from pipewire to pulseaudio on my machine but it was breaking a lot of other things so i couldn't test it properly.

Okay so somehow i was able to setup pulseaudio so i could test properly (although it has other unrelated issue so i cannot use it as daily driver), I have been testing it over few weekends and I can confirm I am not seeing those reconnections while using pulseaudio @pv.

One thing to note is that i tried exclusively using SBC codec on pipewire as well but issue still persisted, so this is not related to codec as well.

pv commented 1 year ago

In your btmon trace above, the disconnect is apparently due to remote device stopping responding. Since there's no access to software running on the device, it's just blind guessing now to see what is it that triggers the device to do that.

The next step would be to make sure the SBC settings are identical, they are generally not starting from frequency etc. You should recompile pipewire from this branch https://gitlab.freedesktop.org/pvir/pipewire/-/tree/sbc-settings see pipewire wiki Troubleshooting for how to do it without overriding system installation. Also try PW 0.3.67.

If it still occurs, take btmon dumps both from PA and PW so it's possible to see what is different.

h3nill commented 1 year ago

@pv Tried both 0.3.67 and sbc-settings branch, experienced same problems on both.

I am trying to get btmon dumps of the time disconnection happens but because they are very random they are hard to catch (once kept btmon running for 1-2hr, only to see it happen after 10 min after i stopped btmon)

Here is btmon dump of pulseaudio-16.1, pipewire-0.3.67 and pipewire-sbc-settings (to see if there are any intial configuration differences b/w them) when everything is working properly:

start btmon dump -> start sound server (i.e. pulseaudio or pipewire) -> connect to device -> play audio for 1-5 sec -> disconnect

pulseaudio-working.btsnoop.log pipewire-0.3.67-working.btsnoop.log pipewire-sbc-settings-working.btsnoop.log

Also once in a while bluetooth state gets completely broken (competely choppy sounds, random delays) and only works properly after laptop restart.

I even tried restart bluetooth and audio related services using:

systemctl --user restart pipewire.service pipewire.socket pipewire-pulse.service pipewire-pulse.socket wireplumber.service bluetooth.target

Tried switching to sbc-settings or pulseaudio it was still broken. Here are btmon dumps during that time:

pipewire-0.3.67-broken-state.btsnoop.log pipewire-sbc-settings-broken-state.btsnoop.log (this is probably redundant, but attached just incase) pulseaudio-16.1-broken-state.btsnoop.log

Only got fixed after restart (this would be probably same as ones first 3 i attached): pipewire-0.3.67-restart.btsnoop.log pipewire-sbc-settings-restart.btsnoop.log pulseaudio-16.1-restart.btsnoop.log

pv commented 1 year ago

pulseaudio-working.btsnoop.log, pipewire-0.3.67-working.btsnoop.log, pipewire-sbc-settings-working.btsnoop.log

Don't see much difference in these. Updated the sbc-settings branch again, this time disabled also delay reporting which was one remaining difference, maybe you can try to see if it changes something.

h3nill commented 1 year ago

Unfortunately still experiencing the problem. Though I was able to catch the disconnection with the lastest sbc-settings branch.

journalctl error was:

Mar 17 22:48:32 henil bluetoothd[556]: src/profile.c:ext_io_disconnected() Unable to get io data for Hands-Free Voice gateway: getpeername: Transport endpoint>

Because I knew dump could have gotten very large (first disconnection happened after 5 hour) i tried to split of the initial handshake from other data. What I did is started the dump connected the device play something for 5 seconds and pause and let all the communication complete.

Then basically restart the btmon in few intervals where everything is going smooth, but dump still got around 56 MB (so attaching a google drive link instead)... The relevant part should be at very last. Also I would like to say thank you for taking your time to debug this!

initial dump: pipewire-sbc-settings-latest.btsnoop.log dump with disconnection: pipewire-sbc-settings-latest-data.btsnoop.log

Related to dump from Pulseaudio because disconnection doesn't happen on it, i assume it would be similar to what I attached previously (i.e. pulseaudio-working.btsnoop.log), but lmk if there is any specific configuration in pulseaudio you want the dump of.

h3nill commented 1 year ago

Also frequency of disconnection increases by alot after the first disconnection (now happening every 15-20 mins)

h3nill commented 1 year ago

Actually one interesting thing to note is that, after the initial disconnection i am seeing subsequent disconnections after roughly multiple of 5 mins (mostly after 5 minutes but can happen occasionally after 10 minutes) journalctl log. This happened previously as well https://github.com/bluez/bluez/issues/419#issuecomment-1438301182

I was using them by only connecting them to laptop. Once I connected my mobile (realme buds support dual device pairing) at around 3:25 and next disconnection happened after 15 or so mintues.

Also when disconnections happens with mobile connected both mobile and laptops bluetooth get disconnected not laptop alone.

Which leads me to believe this might be a bug in liveliness check between the devices (from quick search it seems it is called Supervision Timeout). And when something unexpected happens device just decide to restart which leads to even mobile's bluetooth connection getting resetted.

Does pipewire differ in anyway to pulseaudio in matter of liveliness checks of devices @pv ?

journalctl -xe -u bluetooth ```log Mar 18 12:04:16 henil systemd[1]: Starting Bluetooth service... ░░ Subject: A start job for unit bluetooth.service has begun execution ░░ Defined-By: systemd ░░ Support: https://lists.freedesktop.org/mailman/listinfo/systemd-devel ░░ ░░ A start job for unit bluetooth.service has begun execution. ░░ ░░ The job identifier is 159. Mar 18 12:04:16 henil bluetoothd[507]: Bluetooth daemon 5.66 Mar 18 12:04:16 henil bluetoothd[507]: Starting SDP server Mar 18 12:04:16 henil bluetoothd[507]: profiles/audio/vcp.c:vcp_init() D-Bus experimental not enabled Mar 18 12:04:16 henil bluetoothd[507]: src/plugin.c:plugin_init() Failed to init vcp plugin Mar 18 12:04:16 henil bluetoothd[507]: profiles/audio/mcp.c:mcp_init() D-Bus experimental not enabled Mar 18 12:04:16 henil bluetoothd[507]: src/plugin.c:plugin_init() Failed to init mcp plugin Mar 18 12:04:16 henil bluetoothd[507]: profiles/audio/bap.c:bap_init() D-Bus experimental not enabled Mar 18 12:04:16 henil bluetoothd[507]: src/plugin.c:plugin_init() Failed to init bap plugin Mar 18 12:04:16 henil systemd[1]: Started Bluetooth service. ░░ Subject: A start job for unit bluetooth.service has finished successfully ░░ Defined-By: systemd ░░ Support: https://lists.freedesktop.org/mailman/listinfo/systemd-devel ░░ ░░ A start job for unit bluetooth.service has finished successfully. ░░ ░░ The job identifier is 159. Mar 18 12:04:16 henil bluetoothd[507]: Bluetooth management interface 1.22 initialized Mar 18 12:04:27 henil bluetoothd[507]: Endpoint registered: sender=:1.31 path=/MediaEndpoint/A2DPSink/sbc Mar 18 12:04:27 henil bluetoothd[507]: Endpoint registered: sender=:1.31 path=/MediaEndpoint/A2DPSource/sbc Mar 18 12:32:05 henil bluetoothd[507]: src/profile.c:ext_io_disconnected() Unable to get io data for Hands-Free Voice gateway: getpeername: Transport endpoint is not connected (107) Mar 18 12:53:16 henil bluetoothd[507]: /org/bluez/hci0/dev_74_D7_13_00_72_5C/fd1: fd(40) ready Mar 18 16:00:14 henil bluetoothd[507]: profiles/audio/avdtp.c:handle_unanswered_req() No reply to Close request Mar 18 16:00:19 henil bluetoothd[507]: /org/bluez/hci0/dev_74_D7_13_00_72_5C/sep1/fd2: fd(41) ready Mar 18 17:03:07 henil bluetoothd[507]: src/profile.c:ext_io_disconnected() Unable to get io data for Hands-Free Voice gateway: getpeername: Transport endpoint is not connected (107) Mar 18 17:03:16 henil bluetoothd[507]: src/profile.c:record_cb() Unable to get Hands-Free Voice gateway SDP record: Host is down Mar 18 17:03:26 henil bluetoothd[507]: src/profile.c:record_cb() Unable to get Hands-Free Voice gateway SDP record: Host is down Mar 18 17:03:38 henil bluetoothd[507]: src/profile.c:record_cb() Unable to get Hands-Free Voice gateway SDP record: Host is down Mar 18 17:03:54 henil bluetoothd[507]: src/profile.c:record_cb() Unable to get Hands-Free Voice gateway SDP record: Host is down Mar 18 17:04:18 henil bluetoothd[507]: src/profile.c:record_cb() Unable to get Hands-Free Voice gateway SDP record: Host is down Mar 18 17:04:58 henil bluetoothd[507]: src/profile.c:record_cb() Unable to get Hands-Free Voice gateway SDP record: Host is down Mar 18 17:06:10 henil bluetoothd[507]: src/profile.c:record_cb() Unable to get Hands-Free Voice gateway SDP record: Host is down Mar 18 17:33:04 henil bluetoothd[507]: /org/bluez/hci0/dev_74_D7_13_00_72_5C/fd3: fd(40) ready Mar 18 17:33:28 henil bluetoothd[507]: /org/bluez/hci0/dev_74_D7_13_00_72_5C/sep1/fd4: fd(41) ready Mar 18 17:33:49 henil bluetoothd[507]: /org/bluez/hci0/dev_74_D7_13_00_72_5C/sep1/fd5: fd(41) ready Mar 18 17:34:10 henil bluetoothd[507]: src/profile.c:ext_io_disconnected() Unable to get io data for Hands-Free Voice gateway: getpeername: Transport endpoint is not connected (107) Mar 18 17:34:21 henil bluetoothd[507]: /org/bluez/hci0/dev_74_D7_13_00_72_5C/fd6: fd(40) ready Mar 18 18:27:50 henil bluetoothd[507]: src/profile.c:ext_io_disconnected() Unable to get io data for Hands-Free Voice gateway: getpeername: Transport endpoint is not connected (107) Mar 18 18:51:30 henil bluetoothd[507]: src/profile.c:ext_io_disconnected() Unable to get io data for Hands-Free Voice gateway: getpeername: Transport endpoint is not connected (107) Mar 18 20:42:53 henil bluetoothd[507]: /org/bluez/hci0/dev_74_D7_13_00_72_5C/sep1/fd8: fd(41) ready Mar 18 22:53:13 henil bluetoothd[507]: src/profile.c:ext_io_disconnected() Unable to get io data for Hands-Free Voice gateway: getpeername: Transport endpoint is not connected (107) Mar 18 23:08:24 henil bluetoothd[507]: /org/bluez/hci0/dev_74_D7_13_00_72_5C/sep1/fd9: fd(41) ready Mar 19 01:06:32 henil bluetoothd[507]: src/profile.c:ext_io_disconnected() Unable to get io data for Hands-Free Voice gateway: getpeername: Transport endpoint is not connected (107) Mar 19 01:22:10 henil bluetoothd[507]: /org/bluez/hci0/dev_74_D7_13_00_72_5C/sep1/fd10: fd(41) ready Mar 19 01:40:40 henil bluetoothd[507]: src/profile.c:ext_io_disconnected() Unable to get io data for Hands-Free Voice gateway: getpeername: Transport endpoint is not connected (107) Mar 19 01:49:04 henil bluetoothd[507]: /org/bluez/hci0/dev_74_D7_13_00_72_5C/sep1/fd11: fd(41) ready Mar 19 01:51:16 henil bluetoothd[507]: /org/bluez/hci0/dev_74_D7_13_00_72_5C/sep1/fd12: fd(41) ready Mar 19 02:24:08 henil bluetoothd[507]: src/profile.c:ext_io_disconnected() Unable to get io data for Hands-Free Voice gateway: getpeername: Transport endpoint is not connected (107) Mar 19 02:24:12 henil bluetoothd[507]: /org/bluez/hci0/dev_74_D7_13_00_72_5C/sep1/fd13: fd(42) ready Mar 19 02:43:08 henil bluetoothd[507]: profiles/audio/avdtp.c:handle_unanswered_req() No reply to Close request Mar 19 02:43:10 henil bluetoothd[507]: src/profile.c:record_cb() Unable to get Hands-Free Voice gateway SDP record: Operation already in progress Mar 19 02:43:39 henil bluetoothd[507]: /org/bluez/hci0/dev_74_D7_13_00_72_5C/sep1/fd14: fd(40) ready Mar 19 02:48:33 henil bluetoothd[507]: profiles/audio/avdtp.c:handle_unanswered_req() No reply to Suspend request Mar 19 02:48:33 henil bluetoothd[507]: src/profile.c:ext_io_disconnected() Unable to get io data for Hands-Free Voice gateway: getpeername: Transport endpoint is not connected (107) Mar 19 02:48:34 henil bluetoothd[507]: src/service.c:btd_service_connect() a2dp-sink profile connect failed for 74:D7:13:00:72:5C: Device or resource busy Mar 19 02:48:34 henil bluetoothd[507]: plugins/policy.c:reconnect_timeout() Reconnecting services failed: Device or resource busy (16) Mar 19 02:48:45 henil bluetoothd[507]: /org/bluez/hci0/dev_74_D7_13_00_72_5C/fd15: fd(40) ready Mar 19 02:54:37 henil bluetoothd[507]: src/profile.c:ext_io_disconnected() Unable to get io data for Hands-Free Voice gateway: getpeername: Transport endpoint is not connected (107) Mar 19 02:55:27 henil bluetoothd[507]: /org/bluez/hci0/dev_74_D7_13_00_72_5C/sep1/fd16: fd(41) ready Mar 19 03:02:11 henil bluetoothd[507]: src/profile.c:ext_io_disconnected() Unable to get io data for Hands-Free Voice gateway: getpeername: Transport endpoint is not connected (107) Mar 19 03:02:12 henil bluetoothd[507]: src/service.c:btd_service_connect() a2dp-sink profile connect failed for 74:D7:13:00:72:5C: Device or resource busy Mar 19 03:02:12 henil bluetoothd[507]: plugins/policy.c:reconnect_timeout() Reconnecting services failed: Device or resource busy (16) Mar 19 03:02:14 henil bluetoothd[507]: /org/bluez/hci0/dev_74_D7_13_00_72_5C/fd17: fd(40) ready Mar 19 03:07:43 henil bluetoothd[507]: src/profile.c:ext_io_disconnected() Unable to get io data for Hands-Free Voice gateway: getpeername: Transport endpoint is not connected (107) Mar 19 03:07:44 henil bluetoothd[507]: src/service.c:btd_service_connect() a2dp-sink profile connect failed for 74:D7:13:00:72:5C: Device or resource busy Mar 19 03:07:44 henil bluetoothd[507]: plugins/policy.c:reconnect_timeout() Reconnecting services failed: Device or resource busy (16) Mar 19 03:07:44 henil bluetoothd[507]: /org/bluez/hci0/dev_74_D7_13_00_72_5C/sep1/fd18: fd(40) ready Mar 19 03:13:14 henil bluetoothd[507]: src/profile.c:ext_io_disconnected() Unable to get io data for Hands-Free Voice gateway: getpeername: Transport endpoint is not connected (107) Mar 19 03:13:15 henil bluetoothd[507]: src/service.c:btd_service_connect() a2dp-sink profile connect failed for 74:D7:13:00:72:5C: Device or resource busy Mar 19 03:13:15 henil bluetoothd[507]: src/profile.c:ext_connect() Hands-Free Voice gateway failed connect to 74:D7:13:00:72:5C: Connection refused (111) Mar 19 03:14:19 henil bluetoothd[507]: /org/bluez/hci0/dev_74_D7_13_00_72_5C/fd19: fd(41) ready Mar 19 03:23:20 henil bluetoothd[507]: profiles/audio/avdtp.c:handle_unanswered_req() No reply to Suspend request Mar 19 03:23:20 henil bluetoothd[507]: src/profile.c:ext_io_disconnected() Unable to get io data for Hands-Free Voice gateway: getpeername: Transport endpoint is not connected (107) Mar 19 03:23:21 henil bluetoothd[507]: src/service.c:btd_service_connect() a2dp-sink profile connect failed for 74:D7:13:00:72:5C: Device or resource busy Mar 19 03:23:21 henil bluetoothd[507]: plugins/policy.c:reconnect_timeout() Reconnecting services failed: Device or resource busy (16) Mar 19 03:23:21 henil bluetoothd[507]: /org/bluez/hci0/dev_74_D7_13_00_72_5C/sep1/fd20: fd(40) ready Mar 19 03:38:55 henil bluetoothd[507]: profiles/audio/avdtp.c:handle_unanswered_req() No reply to Suspend request Mar 19 03:38:55 henil bluetoothd[507]: src/profile.c:ext_io_disconnected() Unable to get io data for Hands-Free Voice gateway: getpeername: Transport endpoint is not connected (107) Mar 19 03:38:57 henil bluetoothd[507]: src/profile.c:record_cb() Unable to get Hands-Free Voice gateway SDP record: Operation already in progress Mar 19 03:38:59 henil bluetoothd[507]: plugins/policy.c:reconnect_timeout() Reconnecting services failed: Operation already in progress (114) ```
pv commented 1 year ago

Does pipewire differ in anyway to pulseaudio in matter of liveliness checks of devices

I don't think either of them does something related to this, it is lower level thing. PA/PW only talk to the device via bluez media API, which only specifies the codec capability options, and kernel l2cap socket they get from bluez for audio data, to which they just push the encoded audio packets. So it is very limited interaction, and I think the issue here is some indirect consequence of something they do differently, given that at the time of disconnects it appears only audio data is being sent. I did not see anything unusual in the packet timings and the codec options should now be identical. It may well be the issue is not reproducible with a different bluetooth adapter.

To reduce number of variables, you should also disable HFP/HSP in pipewire, create file e.g. named ~/.config/wireplumber/bluetooth.lua.d/51-hfp.lua containing the line bluez_monitor.properties["bluez5.hfphsp-backend"] = "none".

Note that btmon if started after device connects leads to dump with missing information. You can edit the dumps with wireshark (mark packets + export specified only).

@henil: You can try the latest sbc-settings branch again, using smaller socket buffer might be better.

h3nill commented 1 year ago

You can try the latest sbc-settings branch again, using smaller socket buffer might be better

Issue was still happening on this branch.

To reduce number of variables, you should also disable HFP/HSP in pipewire, create file e.g. named ~/.config/wireplumber/bluetooth.lua.d/51-hfp.lua containing the line bluez_monitor.properties["bluez5.hfphsp-backend"] = "none".

Although the issue hasn't happened for couple of days for me (on pipewire 0.3.67) with hfphsp-backend disabled. Not sure if it was because of disabling the backend or due to any other system update. Will try re-enabling it to see if it happens again.

Meanwhile can anyone else try and see if setting it mitigates the issue for them?

wireplumber config i am using ![image](https://user-images.githubusercontent.com/71698300/227916345-0475364a-5c5e-4f36-9fbe-c0f4ce4a9d68.png)

And @pv is there any way to use wireplumber settings that is configured in ~/.config/wireplumber while using development build? Currently it seems to be using default values only when i do make run. I think it can be set in pipewire/subprojects/wireplumber/src/config, but it would be messy to copy files to that configuration folder and update in both places when i want to change anything.

h3nill commented 1 year ago

Okay, I can confirm after removing that fix I am again seeing those disconnections. I have also confirmed this with one of my friend who had similar issues and disabling hfphsp-backend mitigates the issue.

I am not sure how just keeping it enabled while using a2dp causes disconnections from the device...

CC: @pv

pv commented 1 year ago

Possibly the device does not like some of the HFP commands we send via RFCOMM, maybe thinking it should auto-disconnect after some time. So one should go through the PA and PW btmon dumps, look through what goes differently in the RFCOMM part, and change things in PW one by one to be the same, to determine what is the difference the device does not like.

h3nill commented 1 year ago

Does pipewire send HFP commands even when just using A2DP on SBC?

MASHtm commented 1 year ago

I can confirm that with disabled bluez5.hfphsp-backend I have no disconnects on both my Laptop and Desktop PC as well. I used my "earfun free pro" headphones as before with SBC-XQ Audio profile, because this triggered the disconnects in the shortest time (about 5-10 minutes). I also reconfirmed that the disconnects happen again as soon as I reactivate hfphsp-backend.

My Laptop is a Lenovo Carbon X1 G9 (latest bios/firmware) with Intel AX201 On my Desktop I use a 7392:c611 Edimax Technology Co., Ltd Edimax Bluetooth Adapter with rtl8761bu

Both run on Fedora 37 with bluez-5.66-4.fc37.x86_64 pipewire-0.3.67-1.fc37.x86_64 wireplumber-0.4.14-1.fc37.x86_64

pv commented 1 year ago

Devices use HFP for e.g. battery status reporting, so not only setting up the audio transport.

We seem to not be replying OK to AT+IPHONEACCEV. Try this: https://gitlab.freedesktop.org/pvir/pipewire/-/tree/hfp-ok

MASHtm commented 1 year ago

I rebuilt the f37 SRPM with your patch applied and got no disconnects for about an hour now with hfphsp-backend reenabled.

h3nill commented 1 year ago

Fixed for me as well

Whimfoome commented 1 year ago

Since updating pipewire to version 0.3.69 I no longer experience this issue as well

h3nill commented 1 year ago

~for some reason i am seeing it again, after i cleaned up development build install and installed 0.3.69 from official repo~ fixed after restart

K4R7IK commented 1 year ago

After updating to 0.3.69 I don't experience random disconnects anymore. Thanks for fixing it.