Skip to content

[Focal] Sometimes "bluebinder" service fails to start on boot, breaking Bluetooth

Basically looks like bluebinder.service needs extra time before it's actually launched, it still fails a few times but gets restarted up to 5 times on each boot before it gives up; this should become some conditional that is checked for in /usr/bin/droid/bluebinder_wait.sh or similar.

Here's some potential props of interest:

phablet@ubuntu-phablet:~$ getprop | grep blue
[ro.bluetooth.a2dp_offload.supported]: [true]
[persist.bluetooth.a2dp_offload.cap]: [sbc-aac-aptx-aptxhd-ldac]
[persist.bluetooth.a2dp_offload.disabled]: [false]
[ro.boottime.vendor.bluetooth-1-0-qti]: [14422157232]
[init.svc_debug_pid.vendor.bluetooth-1-0-qti]: [214]
[persist.sys.fflag.override.settings_bluetooth_hearing_aid]: [true]
[ro.vendor.bluetooth.wipower]: [false]
[persist.vendor.qcom.bluetooth.soc]: [cherokee]
[persist.vendor.qcom.bluetooth.scram.enabled]: [false]
[persist.vendor.qcom.bluetooth.enable.splita2dp]: [true]
[persist.vendor.qcom.bluetooth.twsp_state.enabled]: [false]
[persist.vendor.qcom.bluetooth.aac_vbr_ctl.enabled]: [true]
[persist.vendor.qcom.bluetooth.a2dp_offload_cap]: [sbc-aptx-aptxtws-aptxhd-aac-ldac-aptxadaptiver2]
[persist.vendor.qcom.bluetooth.aptxadaptiver2_1_support]: [false]
[init.svc.vendor.bluetooth-1-0-qti]: [running]

Logs from a boot where this fails:

phablet@ubuntu-phablet:~$ systemctl status bluebinder
● bluebinder.service - Simple proxy for using android binder based bluetooth through vhci.
     Loaded: loaded (/lib/systemd/system/bluebinder.service; enabled; vendor preset: enabled)
     Active: failed (Result: protocol) since Tue 2023-02-14 13:11:30 EET; 14h ago
    Process: 2172 ExecStartPre=/usr/bin/droid/bluebinder_wait.sh (code=exited, status=0/SUCCESS)
    Process: 2190 ExecStart=/usr/sbin/bluebinder (code=exited, status=0/SUCCESS)
   Main PID: 2190 (code=exited, status=0/SUCCESS)
     Status: "Exiting."
      Error: 19 (No such device)

...

phablet@ubuntu-phablet:~$ journalctl -b -u bluebinder.service
-- Logs begin at Thu 2022-09-08 12:58:15 EEST, end at Wed 2023-02-15 03:54:03 EET. --
Sep 08 12:58:25 ubuntu-phablet systemd[1]: Starting Simple proxy for using android binder based bluetooth through vhci....
Sep 08 12:58:26 ubuntu-phablet bluebinder_wait.sh[1603]: Waiting for bluetooth service
Feb 14 13:11:28 ubuntu-phablet bluebinder_wait.sh[1603]: Bluetooth service running
Feb 14 13:11:29 ubuntu-phablet bluebinder[1883]: Failed to connect to bluetooth binder service
Feb 14 13:11:28 ubuntu-phablet unknown[1883]: g_main_loop_quit: assertion 'loop != NULL' failed
Feb 14 13:11:28 ubuntu-phablet unknown[1883]: g_io_channel_shutdown: assertion 'channel != NULL' failed
Feb 14 13:11:28 ubuntu-phablet unknown[1883]: g_io_channel_unref: assertion 'channel != NULL' failed
Feb 14 13:11:28 ubuntu-phablet systemd[1]: bluebinder.service: Failed with result 'protocol'.
Feb 14 13:11:28 ubuntu-phablet systemd[1]: Failed to start Simple proxy for using android binder based bluetooth through vhci..
Feb 14 13:11:29 ubuntu-phablet systemd[1]: bluebinder.service: Scheduled restart job, restart counter is at 1.
Feb 14 13:11:29 ubuntu-phablet systemd[1]: Stopped Simple proxy for using android binder based bluetooth through vhci..
Feb 14 13:11:29 ubuntu-phablet systemd[1]: Starting Simple proxy for using android binder based bluetooth through vhci....
Feb 14 13:11:29 ubuntu-phablet bluebinder_wait.sh[1936]: Bluetooth service running
Feb 14 13:11:29 ubuntu-phablet bluebinder[1957]: Failed to connect to bluetooth binder service
Feb 14 13:11:29 ubuntu-phablet unknown[1957]: g_main_loop_quit: assertion 'loop != NULL' failed
Feb 14 13:11:29 ubuntu-phablet unknown[1957]: g_io_channel_shutdown: assertion 'channel != NULL' failed
Feb 14 13:11:29 ubuntu-phablet unknown[1957]: g_io_channel_unref: assertion 'channel != NULL' failed
Feb 14 13:11:29 ubuntu-phablet systemd[1]: bluebinder.service: Failed with result 'protocol'.
Feb 14 13:11:29 ubuntu-phablet systemd[1]: Failed to start Simple proxy for using android binder based bluetooth through vhci..
Feb 14 13:11:29 ubuntu-phablet systemd[1]: bluebinder.service: Scheduled restart job, restart counter is at 2.
Feb 14 13:11:29 ubuntu-phablet systemd[1]: Stopped Simple proxy for using android binder based bluetooth through vhci..
Feb 14 13:11:29 ubuntu-phablet systemd[1]: Starting Simple proxy for using android binder based bluetooth through vhci....
Feb 14 13:11:29 ubuntu-phablet bluebinder_wait.sh[2050]: Bluetooth service running
Feb 14 13:11:29 ubuntu-phablet bluebinder[2062]: Failed to connect to bluetooth binder service
Feb 14 13:11:29 ubuntu-phablet unknown[2062]: g_main_loop_quit: assertion 'loop != NULL' failed
Feb 14 13:11:29 ubuntu-phablet unknown[2062]: g_io_channel_shutdown: assertion 'channel != NULL' failed
Feb 14 13:11:29 ubuntu-phablet unknown[2062]: g_io_channel_unref: assertion 'channel != NULL' failed
Feb 14 13:11:29 ubuntu-phablet systemd[1]: bluebinder.service: Failed with result 'protocol'.
Feb 14 13:11:29 ubuntu-phablet systemd[1]: Failed to start Simple proxy for using android binder based bluetooth through vhci..
Feb 14 13:11:30 ubuntu-phablet systemd[1]: bluebinder.service: Scheduled restart job, restart counter is at 3.
Feb 14 13:11:30 ubuntu-phablet systemd[1]: Stopped Simple proxy for using android binder based bluetooth through vhci..
Feb 14 13:11:30 ubuntu-phablet systemd[1]: Starting Simple proxy for using android binder based bluetooth through vhci....
Feb 14 13:11:30 ubuntu-phablet bluebinder_wait.sh[2145]: Bluetooth service running
Feb 14 13:11:30 ubuntu-phablet bluebinder[2154]: Failed to connect to bluetooth binder service
Feb 14 13:11:30 ubuntu-phablet bluebinder[2154]: g_main_loop_quit: assertion 'loop != NULL' failed
Feb 14 13:11:30 ubuntu-phablet bluebinder[2154]: g_io_channel_shutdown: assertion 'channel != NULL' failed
Feb 14 13:11:30 ubuntu-phablet bluebinder[2154]: g_io_channel_unref: assertion 'channel != NULL' failed
Feb 14 13:11:30 ubuntu-phablet systemd[1]: bluebinder.service: Failed with result 'protocol'.
Feb 14 13:11:30 ubuntu-phablet systemd[1]: Failed to start Simple proxy for using android binder based bluetooth through vhci..
Feb 14 13:11:30 ubuntu-phablet systemd[1]: bluebinder.service: Scheduled restart job, restart counter is at 4.
Feb 14 13:11:30 ubuntu-phablet systemd[1]: Stopped Simple proxy for using android binder based bluetooth through vhci..
Feb 14 13:11:30 ubuntu-phablet systemd[1]: Starting Simple proxy for using android binder based bluetooth through vhci....
Feb 14 13:11:30 ubuntu-phablet bluebinder_wait.sh[2172]: Bluetooth service running
Feb 14 13:11:30 ubuntu-phablet systemd[1]: bluebinder.service: Failed with result 'protocol'.
Feb 14 13:11:30 ubuntu-phablet systemd[1]: Failed to start Simple proxy for using android binder based bluetooth through vhci..
Feb 14 13:11:30 ubuntu-phablet systemd[1]: bluebinder.service: Scheduled restart job, restart counter is at 5.
Feb 14 13:11:30 ubuntu-phablet systemd[1]: Stopped Simple proxy for using android binder based bluetooth through vhci..
Feb 14 13:11:30 ubuntu-phablet systemd[1]: bluebinder.service: Start request repeated too quickly.
Feb 14 13:11:30 ubuntu-phablet systemd[1]: bluebinder.service: Failed with result 'protocol'.
Feb 14 13:11:30 ubuntu-phablet systemd[1]: Failed to start Simple proxy for using android binder based bluetooth through vhci..

Similar logs from a boot where it works:

phablet@ubuntu-phablet:~$ systemctl status bluebinder
● bluebinder.service - Simple proxy for using android binder based bluetooth through vhci.
     Loaded: loaded (/lib/systemd/system/bluebinder.service; enabled; vendor preset: enabled)
     Active: active (running) since Wed 2023-02-15 03:56:23 EET; 47s ago
    Process: 2434 ExecStartPre=/usr/bin/droid/bluebinder_wait.sh (code=exited, status=0/SUCCESS)
    Process: 3097 ExecStartPost=/usr/bin/droid/bluebinder_post.sh (code=exited, status=0/SUCCESS)
   Main PID: 2515 (bluebinder)
     Memory: 432.0K
     CGroup: /system.slice/bluebinder.service
             └─2515 /usr/sbin/bluebinder

...
phablet@ubuntu-phablet:~$ journalctl -b -u bluebinder.service
-- Logs begin at Fri 2023-02-03 00:16:59 EET, end at Wed 2023-02-15 03:57:19 EET. --
Feb 15 03:56:20 ubuntu-phablet bluebinder_wait.sh[1606]: Bluetooth service running
Feb 15 03:56:20 ubuntu-phablet systemd[1]: bluebinder.service: Failed with result 'protocol'.
Feb 15 03:56:20 ubuntu-phablet systemd[1]: Failed to start Simple proxy for using android binder based bluetooth through vhci..
Feb 15 03:56:20 ubuntu-phablet systemd[1]: bluebinder.service: Scheduled restart job, restart counter is at 1.
Feb 15 03:56:20 ubuntu-phablet systemd[1]: Stopped Simple proxy for using android binder based bluetooth through vhci..
Feb 15 03:56:20 ubuntu-phablet systemd[1]: Starting Simple proxy for using android binder based bluetooth through vhci....
Feb 15 03:56:20 ubuntu-phablet bluebinder_wait.sh[2004]: Bluetooth service running
Feb 15 03:56:20 ubuntu-phablet bluebinder[2016]: Failed to connect to bluetooth binder service
Feb 15 03:56:20 ubuntu-phablet bluebinder[2016]: g_main_loop_quit: assertion 'loop != NULL' failed
Feb 15 03:56:20 ubuntu-phablet bluebinder[2016]: g_io_channel_shutdown: assertion 'channel != NULL' failed
Feb 15 03:56:20 ubuntu-phablet bluebinder[2016]: g_io_channel_unref: assertion 'channel != NULL' failed
Feb 15 03:56:20 ubuntu-phablet systemd[1]: bluebinder.service: Failed with result 'protocol'.
Feb 15 03:56:20 ubuntu-phablet systemd[1]: Failed to start Simple proxy for using android binder based bluetooth through vhci..
Feb 15 03:56:20 ubuntu-phablet systemd[1]: bluebinder.service: Scheduled restart job, restart counter is at 2.
Feb 15 03:56:20 ubuntu-phablet systemd[1]: Stopped Simple proxy for using android binder based bluetooth through vhci..
Feb 15 03:56:20 ubuntu-phablet systemd[1]: Starting Simple proxy for using android binder based bluetooth through vhci....
Feb 15 03:56:20 ubuntu-phablet bluebinder_wait.sh[2048]: Bluetooth service running
Feb 15 03:56:20 ubuntu-phablet bluebinder[2059]: Failed to connect to bluetooth binder service
Feb 15 03:56:20 ubuntu-phablet bluebinder[2059]: g_main_loop_quit: assertion 'loop != NULL' failed
Feb 15 03:56:20 ubuntu-phablet bluebinder[2059]: g_io_channel_shutdown: assertion 'channel != NULL' failed
Feb 15 03:56:20 ubuntu-phablet bluebinder[2059]: g_io_channel_unref: assertion 'channel != NULL' failed
Feb 15 03:56:20 ubuntu-phablet systemd[1]: bluebinder.service: Failed with result 'protocol'.
Feb 15 03:56:20 ubuntu-phablet systemd[1]: Failed to start Simple proxy for using android binder based bluetooth through vhci..
Feb 15 03:56:21 ubuntu-phablet systemd[1]: bluebinder.service: Scheduled restart job, restart counter is at 3.
Feb 15 03:56:21 ubuntu-phablet systemd[1]: Stopped Simple proxy for using android binder based bluetooth through vhci..
Feb 15 03:56:21 ubuntu-phablet systemd[1]: Starting Simple proxy for using android binder based bluetooth through vhci....
Feb 15 03:56:21 ubuntu-phablet bluebinder_wait.sh[2167]: Bluetooth service running
Feb 15 03:56:21 ubuntu-phablet bluebinder[2183]: g_main_loop_quit: assertion 'loop != NULL' failed
Feb 15 03:56:21 ubuntu-phablet bluebinder[2183]: Failed to connect to bluetooth binder service
Feb 15 03:56:21 ubuntu-phablet bluebinder[2183]: g_io_channel_shutdown: assertion 'channel != NULL' failed
Feb 15 03:56:21 ubuntu-phablet bluebinder[2183]: g_io_channel_unref: assertion 'channel != NULL' failed
Feb 15 03:56:21 ubuntu-phablet systemd[1]: bluebinder.service: Failed with result 'protocol'.
Feb 15 03:56:21 ubuntu-phablet systemd[1]: Failed to start Simple proxy for using android binder based bluetooth through vhci..
Feb 15 03:56:21 ubuntu-phablet systemd[1]: bluebinder.service: Scheduled restart job, restart counter is at 4.
Feb 15 03:56:21 ubuntu-phablet systemd[1]: Stopped Simple proxy for using android binder based bluetooth through vhci..
Feb 15 03:56:21 ubuntu-phablet systemd[1]: Starting Simple proxy for using android binder based bluetooth through vhci....
Feb 15 03:56:21 ubuntu-phablet bluebinder_wait.sh[2434]: Bluetooth service running
Feb 15 03:56:21 ubuntu-phablet bluebinder[2515]: Own hci index: 1
Feb 15 03:56:21 ubuntu-phablet bluebinder[2515]: delaying writing host command to controller until bt is up
Feb 15 03:56:21 ubuntu-phablet bluebinder[2515]: delaying writing host command to controller until bt is up
Feb 15 03:56:21 ubuntu-phablet bluebinder[2515]: Turning bluetooth on
Feb 15 03:56:23 ubuntu-phablet bluebinder[2515]: Got BLUEBINDER_LOCAL_FEATURES_MASK 0x0
Feb 15 03:56:23 ubuntu-phablet bluebinder[2515]: Bluetooth binder initialized successfully
Feb 15 03:56:23 ubuntu-phablet bluebinder[2515]: Successfully initialized vhci bluetooth
Feb 15 03:56:23 ubuntu-phablet bluebinder[2515]: Turning bluetooth off
Feb 15 03:56:23 ubuntu-phablet systemd[1]: Started Simple proxy for using android binder based bluetooth through vhci..
Edited by Jami Kettunen