Bluetooth is not fully re-initialized when rfkill switch is toggled

[James M. Leddy]

Summary: RFKill switch can disable the bluetooth, but switching it back on doesn't bring the bluetooth all the way up. The bluetooth service must be restarted for it to come back online fully.

Steps:
1. Check Bluetooth status
2. Use wireless switch to disable Bluetooth
3. Use wireless switch to enable Bluetooth

Expected results: In Step 1, BT should be enabled by default, In Step2 BT sould be disabled. In Step 3, BT should be enabled.

Actual results: In Step 3, the Bluetooth adapter is not fully online. The inidicator says that the bluetooth is up, but, one cannot pair devices, transfer files, etc, until the bluetooth service is restarted.

[James M. Leddy (jm-leddy)]

Workaround
==========

61-rfkill-nm-disable-enable.rules
==========================

#the rfkill device number for wifi is inconsistent between platforms * is used
KERNEL!="rfkill*", GOTO="rfkill_nm_disable_enable_end"
ACTION!="change", GOTO="rfkill_nm_disable_enable_end"
#only switch once on wlan event to avoid doubling in the case of bluetooth event, related to rfkill switch
ENV{RFKILL_STATE}=="1" ENV{RFKILL_TYPE}=="wlan" RUN+="nm-disable-enable"
LABEL="rfkill_nm_disable_enable_end"

nm-disable-enable
===============
#!/bin/sh
service bluetooth restart

[James M. Leddy (jm-leddy)]

output of bluetoothd -nd . rfkill switch started on, was turned off, then on again. Please let me know if there are other diagnostic steps that you would like to help move this along.

[James M. Leddy (jm-leddy)]

Initial analysis :

Init:

bluetoothd[1982]: src/main.c:main() Entering main loop
bluetoothd[1982]: src/rfkill.c:rfkill_event() RFKILL event idx 0 type 1 op 0 soft 0 hard 0
bluetoothd[1982]: src/rfkill.c:rfkill_event() RFKILL event idx 1 type 2 op 0 soft 0 hard 0
bluetoothd[1982]: src/rfkill.c:rfkill_event() RFKILL event idx 2 type 2 op 0 soft 0 hard 0
bluetoothd[1982]: src/rfkill.c:rfkill_event() RFKILL event idx 3 type 1 op 0 soft 0 hard 0
bluetoothd[1982]: plugins/hciops.c:init_known_adapters()
bluetoothd[1982]: plugins/hciops.c:init_device() hci0

Flip switch off:

bluetoothd[1982]: src/rfkill.c:rfkill_event() RFKILL event idx 3 type 1 op 2 soft 0 hard 1
bluetoothd[1982]: HCI dev 0 down

Flip switch on:

bluetoothd[1982]: src/rfkill.c:rfkill_event() RFKILL event idx 2 type 2 op 1 soft 0 hard 0
bluetoothd[1982]: src/rfkill.c:rfkill_event() RFKILL event idx 0 type 1 op 2 soft 1 hard 1
bluetoothd[1982]: src/rfkill.c:rfkill_event() RFKILL event idx 1 type 2 op 2 soft 1 hard 1
bluetoothd[1982]: src/rfkill.c:rfkill_event() RFKILL event idx 3 type 1 op 2 soft 0 hard 0
bluetoothd[1982]: HCI dev 0 registered
bluetoothd[1982]: plugins/hciops.c:init_device() hci0
bluetoothd[1982]: Listening for HCI events on hci0
bluetoothd[1982]: plugins/hciops.c:init_device() child 1998 forked
bluetoothd[1982]: src/rfkill.c:rfkill_event() RFKILL event idx 4 type 2 op 0 soft 0 hard 0
bluetoothd[1982]: src/rfkill.c:rfkill_event() RFKILL event idx 4 type 2 op 2 soft 0 hard 0
bluetoothd[1982]: plugins/hciops.c:read_local_features_complete() Got features for hci0
bluetoothd[1982]: plugins/hciops.c:read_local_version_complete() Got version for hci0
bluetoothd[1982]: plugins/hciops.c:read_bd_addr_complete() hci0 status 0
bluetoothd[1982]: plugins/hciops.c:read_bd_addr_complete() Got bdaddr for hci0
bluetoothd[1982]: plugins/hciops.c:read_local_name_complete() hci0 status 0
bluetoothd[1982]: plugins/hciops.c:read_local_name_complete() Got name for hci0
bluetoothd[1982]: plugins/hciops.c:read_tx_power_complete() hci0 status 0
bluetoothd[1982]: plugins/hciops.c:update_ext_inquiry_response() hci0
bluetoothd[1982]: HCI dev 0 up

Some other event I don't know what is, may be cleanup:

bluetoothd[1982]: src/rfkill.c:rfkill_event() RFKILL event idx 0 type 1 op 2 soft 0 hard 0
bluetoothd[1982]: src/rfkill.c:rfkill_event() RFKILL event idx 1 type 2 op 2 soft 0 hard 0
bluetoothd[1982]: src/adapter.c:adapter_remove() Removing adapter /org/bluez/1982/hci0
bluetoothd[1982]: src/sdpd-service.c:remove_record_from_server() Removing record with handle 0x10005

What I find interesting is that idx 0,1 are not re-enabled when the switch is flicked back on, only some time later, if I'm reading the output of rfkill_event() correctly.

[James M. Leddy (jm-leddy)]

On second thought, the last event is not cleanup, since it is recognizing the switch as _on_ for idx{0,1}. It looks like the device might have to be initialized first before it sends the signal that the rfkill switch has been turned on. Here is more complete what's going on before that:

bluetoothd[1982]: Adapter /org/bluez/1982/hci0 has been enabled
bluetoothd[1982]: plugins/hciops.c:hciops_set_discoverable() hci0 discoverable 0
bluetoothd[1982]: plugins/hciops.c:hciops_set_pairable() hci0 pairable 1
bluetoothd[1982]: src/adapter.c:btd_adapter_unref() 0x7fc70e13b6b0: ref=6
bluetoothd[1982]: plugins/hciops.c:child_exit() child 1998 exited
bluetoothd[1982]: src/adapter.c:register_agent() Agent registered for hci0 at :1.39:/org/bluez/agent/hci0
bluetoothd[1982]: plugins/hciops.c:read_tx_power_complete() hci0 status 0
bluetoothd[1982]: plugins/hciops.c:update_ext_inquiry_response() hci0
bluetoothd[1982]: plugins/hciops.c:update_ext_inquiry_response() hci0
bluetoothd[1982]: plugins/hciops.c:read_local_name_complete() hci0 status 0
bluetoothd[1982]: plugins/hciops.c:update_ext_inquiry_response() hci0
bluetoothd[1982]: plugins/hciops.c:read_simple_pairing_mode_complete() hci0 status 0
bluetoothd[1982]: plugins/hciops.c:update_ext_inquiry_response() hci0
bluetoothd[1982]: plugins/hciops.c:read_local_name_complete() hci0 status 0
bluetoothd[1982]: plugins/hciops.c:update_ext_inquiry_response() hci0
bluetoothd[1982]: plugins/hciops.c:read_scan_complete() hci0 status 0
bluetoothd[1982]: src/adapter.c:adapter_mode_changed() old 0x00 new 0x02
bluetoothd[1982]: src/adapter.c:adapter_set_limited_discoverable() FALSE
bluetoothd[1982]: plugins/hciops.c:hciops_set_limited_discoverable() hci0 limited 0
bluetoothd[1982]: src/adapter.c:set_mode_complete()
bluetoothd[1982]: src/rfkill.c:rfkill_event() RFKILL event idx 0 type 1 op 2 soft 0 hard 0
bluetoothd[1982]: src/rfkill.c:rfkill_event() RFKILL event idx 1 type 2 op 2 soft 0 hard 0

[James M. Leddy (jm-leddy)]

The only noticeable differences in output between initialization and the re-enablement of device via rfkill.

1) aforementioned idx{0,1} are blocked until initialization is done

2) bluetoothd[1982]: src/rfkill.c:rfkill_event() RFKILL event idx 4 type 2 op 0 soft 0 hard 0
   bluetoothd[1982]: src/rfkill.c:rfkill_event() RFKILL event idx 4 type 2 op 2 soft 0 hard 0

Occur only in re-enablement

3) child process fork/exiting takes a lot longer when re-enabling as opposed to init.

[Mathieu Trudel-Lapierre (cyphermox)]

This seems to work pretty well for me right now if you omit the issue of the bluetooth applet not properly seeing the new enabled state after rfkill has been toggled (it never comes back with the full menu unless you change a config in the wizard or turn it off/on again via the menu). Bluetooth functions properly though, I was able to send and receive files successfully.

[Mathieu Trudel-Lapierre (cyphermox)]

Anthony or James, please confirm: this was for a Dell device right? It's the only place so far I've been able to reproduce this kind of behavior. Seems to be because the killswitch actually removes the bluetooth device altogether.

[Anthony Wong (anthonywong)]

Yes, this is a Dell device. And will killswitch is enabled, device no longer shows in lsusb.

[Jesse Sung (wenchien)]

This patch is not mandatory for this issue, but it fixes an error message when RFKILL switch is turned off:

bluetoothd[5416]: sap/manager.c:sap_server_probe() path /org/bluez/5416/hci0
bluetoothd[5416]: sap-dummy interface org.bluez.SimAccessTest init failed on path /org/bluez/test
bluetoothd[5416]: Sap driver initialization failed.
bluetoothd[5416]: sap-server: Operation not permitted (1)

[Jesse Sung (wenchien)]

This patch is for

bluetoothd[5416]: audio/manager.c:gateway_server_init() audio.conf: Key file does not have key 'Master'
bluetoothd[5416]: rfcomm_bind: Address already in use (98)
bluetoothd[5416]: audio-gateway: Operation not permitted (1)

[Jesse Sung (wenchien)]

On certain devices, module would be powered off after RFKILL enabled. When RFKILL is disabled again, update_menu_items() would be called with has_powered_adapter set to TRUE, but the bluetooth_applet_get_killswitch_state() still thinks RFKILL is in a blocked state and refuses to enable full menu.
Explicity emit an update-menu signal when killswitch state changed fix this.

[Jesse Sung (wenchien)]

Patched bluez and gnome-bluetooth packages can be found at
http://people.canonical.com/~jesse/lp907818/

Please give them a try to see if this issue is gone, and also make sure that they do not break anything on other platforms. :)

Thank you.

[Ubuntu Foundations Team Bug Bot (crichton)]

The attachment "patch for bluez (optional)" of this bug report has been identified as being a patch. The ubuntu-reviewers team has been subscribed to the bug report so that they can review the patch. In the event that this is in fact not a patch you can resolve this situation by removing the tag 'patch' from the bug report and editing the attachment so that it is not flagged as a patch. Additionally, if you are member of the ubuntu-reviewers team please also unsubscribe the team from this bug report.

[This is an automated message performed by a Launchpad user owned by Brian Murray. Please contact him regarding any issues with the action taken in this bug report.]

[Mathieu Trudel-Lapierre (cyphermox)]

Well, patch https://launchpadlibrarian.net/96987064/11-explicitly_close.patch seems at least a little incorrect; it seems to be as though you should be closing the io channel before it gets unref'd ;)

Also, g_io_channel_close() is deprecated, it would be better to use g_io_channel_shutdown().

Do you need sponsoring for these patches?

[Jesse Sung (wenchien)]

Hi Mathieu,

Sorry, didn't notice that it's deprecated. An updated patch is attached.

And yes, please sponsor these patches, thank you. :)

[Mathieu Trudel-Lapierre (cyphermox)]

In progress :) I'll upload this in a few minutes once I can successfully test this.

It's nice to see we got the same patch for the gnome-bluetooth part of the fix independently.

[Launchpad Janitor (janitor)]

This bug was fixed in the package bluez - 4.98-2ubuntu7

---------------
bluez (4.98-2ubuntu7) precise; urgency=low

  * debian/patches/10-unregister_interface_on_exit.patch: unregister the SAP
    interface on exit. Thanks to Jesse Sung for the patch.
  * debian/patches/11-explicitly_close.patch: make sure the io channel for
    HFP is properly closed on exit. Thanks to Jesse Sung for the patch.
    (LP: #907818)
 -- Mathieu Trudel-Lapierre <email address hidden> Wed, 21 Mar 2012 15:27:57 -0400

[Launchpad Janitor (janitor)]

This bug was fixed in the package gnome-bluetooth - 3.2.2-0ubuntu4

---------------
gnome-bluetooth (3.2.2-0ubuntu4) precise; urgency=low

  * debian/patches/menu_update_on_rfkill.patch: make sure the menu gets updated
    properly when the killswitch state is changed. Specifically, notify for the
    applet to show the full menu, so that it can be displayed again when coming
    back from BLOCKED state. This fixes an issue specific to Dell systems where
    the devices are removed then re-added when the rfkill state is toggled.
    (LP: #907818)
 -- Mathieu Trudel-Lapierre <email address hidden> Wed, 21 Mar 2012 16:56:46 -0400