Hi Luiz,
On Wed, Jun 25, 2014 at 12:27 AM, Luiz Augusto von Dentz
<luiz.dentz@xxxxxxxxx> wrote:
> Hi Petri,
>
> On Wed, Jun 25, 2014 at 3:44 AM, Petri Gynther <pgynther@xxxxxxxxxx> wrote:
>> Hi Luiz,
>>
>> On Tue, Jun 24, 2014 at 4:48 AM, Luiz Augusto von Dentz
>> <luiz.dentz@xxxxxxxxx> wrote:
>>> Hi Petri,
>>>
>>> On Tue, Jun 24, 2014 at 3:37 AM, Petri Gynther <pgynther@xxxxxxxxxx> 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
--
To unsubscribe from this list: send the line "unsubscribe linux-bluetooth" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
