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.
-- Petri
Hi Luiz,
On Wed, Jun 25, 2014 at 12:27 AM, Luiz Augusto von Dentz
<[email protected]> wrote:
> Hi Petri,
>
> On Wed, Jun 25, 2014 at 3:44 AM, Petri Gynther <[email protected]> wrote:
>> Hi Luiz,
>>
>> On Tue, Jun 24, 2014 at 4:48 AM, Luiz Augusto von Dentz
>> <[email protected]> wrote:
>>> Hi Petri,
>>>
>>> On Tue, Jun 24, 2014 at 3:37 AM, Petri Gynther <[email protected]> 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
Hi Petri,
On Wed, Jun 25, 2014 at 3:44 AM, Petri Gynther <[email protected]> wrote:
> Hi Luiz,
>
> On Tue, Jun 24, 2014 at 4:48 AM, Luiz Augusto von Dentz
> <[email protected]> wrote:
>> Hi Petri,
>>
>> On Tue, Jun 24, 2014 at 3:37 AM, Petri Gynther <[email protected]> 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.
--
Luiz Augusto von Dentz
Hi Luiz,
On Tue, Jun 24, 2014 at 4:48 AM, Luiz Augusto von Dentz
<[email protected]> wrote:
> Hi Petri,
>
> On Tue, Jun 24, 2014 at 3:37 AM, Petri Gynther <[email protected]> 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().
-- Petri
>
>
> --
> Luiz Augusto von Dentz
Hi Petri,
On Tue, Jun 24, 2014 at 3:37 AM, Petri Gynther <[email protected]> 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.
--
Luiz Augusto von Dentz