Return-Path: MIME-Version: 1.0 In-Reply-To: References: Date: Wed, 25 Jun 2014 10:49:23 -0700 Message-ID: Subject: Re: BlueZ 5.19: BLE HoG device reconnect issues From: Petri Gynther To: Luiz Augusto von Dentz Cc: linux-bluetooth Content-Type: text/plain; charset=UTF-8 Sender: linux-bluetooth-owner@vger.kernel.org List-ID: Hi Luiz, On Wed, Jun 25, 2014 at 12:27 AM, Luiz Augusto von Dentz wrote: > Hi Petri, > > On Wed, Jun 25, 2014 at 3:44 AM, Petri Gynther wrote: >> Hi Luiz, >> >> On Tue, Jun 24, 2014 at 4:48 AM, Luiz Augusto von Dentz >> wrote: >>> Hi Petri, >>> >>> On Tue, Jun 24, 2014 at 3:37 AM, Petri Gynther wrote: >>>> With BlueZ 5.19 stack and BLE HoG remote controls, I'm seeing 3 >>>> different issues when trying to reconnect a previously paired BLE HoG >>>> remote control: >>>> >>>> Full log: >>>> [72241.012] bluez: bluetoothd[29263]: >>>> src/adapter.c:discovering_callback() hci0 type 6 discovering 1 >>>> [72251.269] bluez: bluetoothd[29263]: >>>> src/adapter.c:device_found_callback() hci0 addr 88:33:14:E6:XX:XX, >>>> rssi -81 flags 0x0000 eir_len 16 >>>> [72251.270] bluez: bluetoothd[29263]: src/device.c:device_set_legacy() legacy 0 >>>> [72251.270] bluez: bluetoothd[29263]: src/adapter.c:stop_passive_scanning() >>>> [72251.270] bluez: bluetoothd[29263]: >>>> src/adapter.c:discovering_callback() hci0 type 6 discovering 0 >>>> [72251.270] bluez: bluetoothd[29263]: >>>> src/adapter.c:trigger_passive_scanning() >>>> [72251.270] bluez: bluetoothd[29263]: >>>> src/adapter.c:stop_passive_scanning_complete() status 0x0b (Rejected) >>>> [72251.270] bluez: bluetoothd[29263]: Stopping passive scanning failed: Rejected >>>> [72255.015] bluez: bluetoothd[29263]: >>>> src/adapter.c:passive_scanning_complete() status 0x00 >>>> [72255.015] bluez: bluetoothd[29263]: >>>> src/adapter.c:discovering_callback() hci0 type 6 discovering 1 >>>> [72258.550] bluez: bluetoothd[29263]: >>>> src/adapter.c:device_found_callback() hci0 addr 88:33:14:E6:XX:XX, >>>> rssi -76 flags 0x0000 eir_len 16 >>>> [72258.551] bluez: bluetoothd[29263]: src/device.c:device_set_legacy() legacy 0 >>>> [72258.551] bluez: bluetoothd[29263]: src/adapter.c:stop_passive_scanning() >>>> [72258.551] bluez: bluetoothd[29263]: >>>> src/adapter.c:device_found_callback() hci0 addr CB:36:E5:F5:XX:XX, >>>> rssi -82 flags 0x0000 eir_len 36 >>>> [72258.558] bluez: bluetoothd[29263]: >>>> src/adapter.c:stop_passive_scanning_complete() status 0x00 (Success) >>>> [72258.558] bluez: bluetoothd[29263]: src/device.c:device_connect_le() >>>> Connection attempt to: 88:33:14:E6:XX:XX >>>> [72258.558] bluez: bluetoothd[29263]: >>>> src/adapter.c:discovering_callback() hci0 type 6 discovering 0 >>>> [72278.629] bluez: bluetoothd[29263]: >>>> src/adapter.c:connect_failed_callback() hci0 88:33:14:E6:XX:XX status >>>> 2 >>>> [72278.629] bluez: bluetoothd[29263]: plugins/policy.c:conn_fail_cb() status 2 >>>> [72278.629] bluez: bluetoothd[29263]: >>>> src/adapter.c:bonding_attempt_complete() hci0 bdaddr 88:33:14:E6:XX:XX >>>> type 1 status 0x2 >>>> [72278.629] bluez: bluetoothd[29263]: >>>> src/device.c:device_bonding_complete() bonding (nil) status 0x02 >>>> [72278.629] bluez: bluetoothd[29263]: >>>> src/device.c:device_bonding_failed() status 2 >>>> [72278.629] bluez: bluetoothd[29263]: src/adapter.c:resume_discovery() >>>> [72278.629] bluez: bluetoothd[29263]: src/device.c:att_connect_cb() >>>> connect error: Transport endpoint is not connected (134) >>>> [72278.629] bluez: bluetoothd[29263]: src/device.c:att_error_cb() >>>> Enabling automatic connections >>>> [72278.630] bluez: bluetoothd[29263]: >>>> src/adapter.c:adapter_connect_list_add() ignoring already added device >>>> /org/bluez/hci0/dev_88_33_14_E6_XX_XX >>>> >>>> Issues 1 and 2: >>>> [72251.270] bluez: bluetoothd[29263]: src/adapter.c:stop_passive_scanning() >>>> [72251.270] bluez: bluetoothd[29263]: >>>> src/adapter.c:discovering_callback() hci0 type 6 discovering 0 >>>> [72251.270] bluez: bluetoothd[29263]: >>>> src/adapter.c:trigger_passive_scanning() >>>> [72251.270] bluez: bluetoothd[29263]: >>>> src/adapter.c:stop_passive_scanning_complete() status 0x0b (Rejected) >>>> [72251.270] bluez: bluetoothd[29263]: Stopping passive scanning failed: Rejected >>>> >>>> 1) device_found_callback() -> update_found_devices() -> >>>> stop_passive_scanning() needs to stop passive scanning because BlueZ >>>> is about to connect to previously paired BLE device. But, >>>> discovering_callback() doesn't take the pending BLE connection into >>>> account and still calls trigger_passive_scanning() when it shouldn't. >>>> >>>> 2) stop_passive_scanning() can actually fail because passive scanning >>>> was already stopped in kernel due to passive scan timer expiring. But, >>>> stop_passive_scanning_complete() handles the Reject case as an error >>>> and never attempts the pending BLE connection in that case. >>>> >>>> Issue 3: >>>> [72278.629] bluez: bluetoothd[29263]: src/device.c:att_connect_cb() >>>> connect error: Transport endpoint is not connected (134) >>>> [72278.629] bluez: bluetoothd[29263]: src/device.c:att_error_cb() >>>> Enabling automatic connections >>>> [72278.630] bluez: bluetoothd[29263]: >>>> src/adapter.c:adapter_connect_list_add() ignoring already added device >>>> /org/bluez/hci0/dev_88_33_14_E6_XX_XX >>>> >>>> If there is an error connecting to BLE device, att_error_cb() adds the >>>> failed device back to adapter connect list, but if it is already >>>> there, no code actually calls trigger_passive_scanning(). So, from >>>> this point on, no BLE device is ever going to reconnect back to BlueZ, >>>> because the passive scanning is disabled and nothing will re-enable >>>> it. >>>> >>>> >>>> Here is my proposed diff for fixing these issues: >>>> @@ -1228,7 +1228,7 @@ static void >>>> stop_passive_scanning_complete(uint8_t status, uint16_t length, >>>> dev = adapter->connect_le; >>>> adapter->connect_le = NULL; >>>> >>>> - if (status != MGMT_STATUS_SUCCESS) { >>>> + if (status != MGMT_STATUS_SUCCESS && status != MGMT_STATUS_REJECTED) { >>>> error("Stopping passive scanning failed: %s", >>>> mgmt_errstr(status)); >>>> return; >>>> >>>> @@ -1500,6 +1500,10 @@ static void discovering_callback(uint16_t >>>> index, uint16_t length, >>>> * passive scanning attempt. >>>> */ >>>> if (!adapter->discovery_list) { >>>> + if (adapter->connect_le) { >>>> + DBG("LE connect pending, skip >>>> trigger_passive_scanning"); >>>> + return; >>>> + } >>>> trigger_passive_scanning(adapter); >>>> return; >>>> } >>>> >>>> @@ -3675,6 +3676,7 @@ static void att_error_cb(const GError *gerr, >>>> gpointer user_data) >>>> if (device_get_auto_connect(device)) { >>>> DBG("Enabling automatic connections"); >>>> adapter_connect_list_add(device->adapter, device); >>>> + trigger_passive_scanning(device->adapter); >>>> } >>>> } >>>> >>>> >>>> Let me know if this looks good. I'll then e-mail proper patch for review. >>> >>> Haven't tested it yet but has this code been changed recently? I >>> wonder how does 5.20 behave in this regard since I did change some >>> parts of uHID implementation but not the scanning logic. Anyway in >>> future we will be changing the scanning logic and let the kernel do >>> the scanning (real passive scanning and perhaps whitelist) for us but >>> in the meantime it is good to have this fixed if still reproducible >>> with 5.20. >> >> I just tested with BlueZ 5.20, and I'm seeing the same 3 issues. I'll >> e-mail patches shortly. I'll fix issue #3 inside >> adapter_connect_list_add(), instead of modifying att_error_cb(). > > I could not reproduce it, Ive turned the device off and then back to > on and it did reconnects, perhaps there is something else that you are > doing to trigger the problem. Btw someone reported that the microsoft > arc also doesn't reconnect but it seems to be after restarting > bluetoothd which I haven't tried. > I just mailed out the patches. I'm able to reproduce this very easily with BlueZ 5.20. Here is one instance (with my patches in place): [56616.293] bluez: bluetoothd[931]: src/adapter.c:device_found_callback() hci0 addr 88:33:14:E6:XX:XX, rssi -66 flags 0x0000 eir_len 16 [56616.293] bluez: bluetoothd[931]: src/device.c:device_set_legacy() legacy 0 [56616.294] bluez: bluetoothd[931]: src/adapter.c:stop_passive_scanning() [56616.294] bluez: bluetoothd[931]: src/adapter.c:discovering_callback() hci0 type 6 discovering 0 => discovering_callback() no longer calls trigger_passive_scanning() since BLE connection is pending [56616.294] bluez: bluetoothd[931]: src/adapter.c:stop_passive_scanning_complete() status 0x0b (Rejected) => stop_passive_scanning_complete() considers Rejected as success and proceeds with BLE connection [56616.294] bluez: bluetoothd[931]: src/device.c:device_connect_le() Connection attempt to: 88:33:14:E6:XX:XX [56623.514] bluez: bluetoothd[931]: src/adapter.c:connected_callback() hci0 device 88:33:14:E6:XX:XX connected eir_len 0 [56624.124] bluez: bluetoothd[931]: attrib/gattrib.c:g_attrib_ref() 0x4b8228: ref=1 [56624.124] bluez: bluetoothd[931]: attrib/gattrib.c:g_attrib_ref() 0x4b8228: ref=2 [56624.124] bluez: bluetoothd[931]: src/adapter.c:adapter_connect_list_remove() /org/bluez/hci0/dev_88_33_14_E6_XX_XX removed from ... connect_list [56624.125] bluez: bluetoothd[931]: src/adapter.c:stop_passive_scanning() [56624.125] bluez: bluetoothd[931]: attrib/gattrib.c:g_attrib_ref() 0x4b8228: ref=3 ... -- Petri > > -- > Luiz Augusto von Dentz