Re: BlueZ 5.19: BLE HoG device reconnect issues

Hi Luiz,

On Tue, Jun 24, 2014 at 4:48 AM, Luiz Augusto von Dentz
[off-list ref] wrote:

Hi Petri,

On Tue, Jun 24, 2014 at 3:37 AM, Petri Gynther [off-list ref] wrote:

quoted

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().

-- Petri

--
Luiz Augusto von Dentz