Help needed to setup 6loble using IPSP sample


Vakul Garg <vakul.garg@...>
 

Hi

 

I am using frdm-kw41z (running hci_blackbox firmware from nxp) stacked over frdm-k64f running zephyr sample IPSP.

In this config, frdm-kw41z acts as bluetooth controller and frdm-k64f acts bluetooth host.

 

On the peer end, a linux machine is attached with another frdm-kw41z with same hci_blackbox firmware as above (but with different BD address).

 

On, running 'hcitool lescan' on linux machine, it can detect the peer IPSP node.

However, running 'hcitool lecc <ipsp node bd address>' causes following error prints on zephyr console.

 

net> [bt] [ERR] hci_acl: Unable to find conn for handle 32

[bt] [ERR] le_data_len_change: Unable to lookup conn for handle 32

net> [bt] [ERR] hci_num_completed_packets: No connection for handle 32

 

My colleague (Maureen – thanks !!) bisected the git and found that following commit is to blame.

Indeed, removing it solves the issue.

 

--------------------------------------------------------------------------------------

commit 56f79f817e679857e385a14f9a7e9b951dbc626e

Author: Johan Hedberg <johan.hedberg@...>

Date:   Thu Oct 5 09:43:56 2017 +0300

 

    Bluetooth: Add support for Link Layer Privacy

--------------------------------------------------------------------------------------

 

Can someone please advise me if I am missing some step or is it a bug that needs to be logged?

The same issue causes problem with other Bluetooth examples such peripheral_hr etc.

 

Regards

 

Vakul

 


Johan Hedberg
 

Hi Vakul,

On Tue, Nov 21, 2017, Vakul Garg wrote:
I am using frdm-kw41z (running hci_blackbox firmware from nxp) stacked over frdm-k64f running zephyr sample IPSP.
In this config, frdm-kw41z acts as bluetooth controller and frdm-k64f acts bluetooth host.

On the peer end, a linux machine is attached with another frdm-kw41z with same hci_blackbox firmware as above (but with different BD address).

On, running 'hcitool lescan' on linux machine, it can detect the peer IPSP node.
However, running 'hcitool lecc <ipsp node bd address>' causes following error prints on zephyr console.

net> [bt] [ERR] hci_acl: Unable to find conn for handle 32
[bt] [ERR] le_data_len_change: Unable to lookup conn for handle 32
net> [bt] [ERR] hci_num_completed_packets: No connection for handle 32

My colleague (Maureen - thanks !!) bisected the git and found that following commit is to blame.
Indeed, removing it solves the issue.

--------------------------------------------------------------------------------------
commit 56f79f817e679857e385a14f9a7e9b951dbc626e
Author: Johan Hedberg <johan.hedberg@intel.com<mailto:johan.hedberg@intel.com>>
Date: Thu Oct 5 09:43:56 2017 +0300

Bluetooth: Add support for Link Layer Privacy
--------------------------------------------------------------------------------------

Can someone please advise me if I am missing some step or is it a bug that needs to be logged?
The same issue causes problem with other Bluetooth examples such peripheral_hr etc.
Have you verified that the handle value 32 is valid, i.e. the controller
gave that in a prior LE Connection Complete event? It would help
investigate the issue if you could get the entire log and also the HCI
log of what's happening. It's not clear to me how the LL Privacy patch
could influence this.

Johan


Vakul Garg <vakul.garg@...>
 

Hi Johan

Let me first admit that I am using BLE for first time and might be missing some basic step.

I simply followed steps from IPSP sample's README. The steps work fine on the older commit I mentioned.

Have you verified that the handle value 32 is valid, i.e. the controller gave that
in a prior LE Connection Complete event?
The linux console shows up connection handle 32 has been connected.

Here are the zephyr logs you requested.
I have used:

CONFIG_BT_PRIVACY=n
CONFIG_BT_DEBUG=y
CONFIG_BT_DEBUG_HCI_CORE=n
CONFIG_BT_DEBUG_CONN=y
CONFIG_BT_DEBUG_KEYS=y
CONFIG_BT_DEBUG_L2CAP=y
CONFIG_BT_DEBUG_SMP=y
CONFIG_BT_DEBUG_SDP=y

Turning CONFIG_BT_DEBUG_HCI_CORE=y causes 'hcitool lescan' to keep waiting almost infinitely.
Also 'hcitool lecc' keeps waiting. Please let me know if you need something more.

Regards,
Vakul

[bt] [DBG] hci_tx_thread: (0x200006f8) Started
[bt] [DBG] bt_conn_prepare_events: (0x200006f8)
[bt] [DBG] hci_tx_thread: (0x200006f8) Calling k_poll with 2 events
[bt] [DBG] bt_hci_cmd_create: (0x20001998) opcode 0x0c03 param_len 0
[bt] [DBG] bt_hci_cmd_create: (0x20001998) buf 0x20004814
[bt] [DBG] bt_hci_cmd_send_sync: (0x20001998) buf 0x20004814 opcode 0x0c03 len 3
[bt] [DBG] process_events: (0x200006f8) count 2
[bt] [DBG] process_events: (0x200006f8) ev->state 4
[bt] [DBG] send_cmd: (0x200006f8) calling net_buf_get
[bt] [DBG] send_cmd: (0x200006f8) calling sem_take_wait
[bt] [DBG] send_cmd: (0x200006f8) Sending command 0x0c03 (buf 0x20004814) to driver
[bt] [DBG] bt_send: (0x200006f8) buf 0x20004814 len 3 type 0
[bt] [DBG] process_events: (0x200006f8) ev->state 0
[bt] [DBG] bt_conn_prepare_events: (0x200006f8)
[bt] [DBG] hci_t[bt] [DBG] bt_buf_get_cmd_complete: (0x200006f8) sent_cmd 0x20004814
x_thread: (0x200006f8) Calling k_poll with 2 events
[bt] [DBG] bt_hci_cmd_send_sync: (0x20001998) opcode 0x0c03 status 0x00
[bt] [DBG] hci_reset_complete: (0x20001998) status 14
[bt] [DBG] bt_hci_cmd_create: (0x20001998) opcode 0x1003 param_len 0
[bt] [DBG] bt_hci_cmd_create: (0x20001998) buf 0x20004878
[bt] [DBG] bt_hci_cmd_send_sync: (0x20001998) buf 0x20004878 opcode 0x1003 len 3
[bt] [DBG] process_events: (0x200006f8) count 2
[bt] [DBG] process_events: (0x200006f8) ev->state 4
[bt] [DBG] send_cmd: (0x200006f8) calling net_buf_get
[bt] [DBG] send_cmd: (0x200006f8) calling sem_take_wait
[bt] [DBG] bt_hci_cmd_send_sync: (0x20001998) opcode 0x1003 status 0x6a
[ipsp] [INF] init_app: Run IPSP sample
[ipsp] [INF] listen: Starting to wait
shell> delaying
shell> delaying
[ipsp] [INF] init_app: Run IPSP sample
[ipsp] [INF] listen: Starting to wait
shell> delaying
[bt] [DBG] bt_conn_prepare_events: (0x200006f8)
[bt] [DBG] bt_conn_prepare_events: (0x200006f8)
[bt] [DBG] bt_conn_prepare_events: (0x200006f8)
[bt] [DBG] bt_conn_prepare_events: (0x200006f8)
[bt] [DBG] bt_conn_prepare_events: (0x200006f8)
[bt] [DBG] bt_conn_prepare_events: (0x200006f8)
[bt] [DBG] bt_conn_prepare_events: (0x200006f8)
[bt] [DBG] bt_conn_prepare_events: (0x200006f8)
[bt] [DBG] bt_conn_prepare_events: (0x200006f8)
[bt] [DBG] bt_conn_prepare_events: (0x200006f8)
[bt] [DBG] bt_conn_prepare_events: (0x200006f8)
[bt] [WRN] set_flow_control: Controller to host flow control not supported
[bt] [DBG] bt_conn_prepare_events: (0x200006f8)
[bt] [DBG] bt_conn_prepare_events: (0x200006f8)
[bt] [DBG] bt_conn_prepare_events: (0x200006f8)
[bt] [DBG] bt_conn_prepare_events: (0x200006f8)
[bt] [DBG] bt_conn_prepare_events: (0x200006f8)
[bt] [DBG] bt_conn_prepare_events: (0x200006f8)
[bt] [DBG] bt_conn_prepare_events: (0x200006f8)
[bt] [DBG] bt_conn_prepare_events: (0x200006f8)
[bt] [DBG] bt_conn_prepare_events: (0x200006f8)
[bt] [WRN] hci_vs_init: Vendor HCI extensions not available
[bt] [INF] show_dev_info: Identity: 00:60:37:00:00:16 (public)
[bt] [INF] show_dev_info: HCI: version 4.2 (0x08) revision 0x000b, manufacturer 0x0025
[bt] [INF] show_dev_info: LMP: version 4.2 (0x08) subver 0x0123
[bt] [DBG] bt_l2cap_le_fixed_chan_register: (0x20001998) CID 0x0004
[bt] [DBG] bt_l2cap_le_fixed_chan_register: (0x20001998) CID 0x0006
[bt] [DBG] bt_smp_init: (0x20001998) LE SC enabled
[bt] [DBG] bt_conn_prepare_events: (0x200006f8)
[bt] [DBG] bt_l2cap_le_fixed_chan_register: (0x20001998) CID 0x0005
[bt] [DBG] bt_conn_prepare_events: (0x200006f8)
[bt] [DBG] bt_smp_pkey_ready: (0x200003b4)
[bt] [DBG] bt_conn_prepare_events: (0x200006f8)
[bt] [DBG] bt_conn_prepare_events: (0x200006f8)
[bt] [DBG] bt_conn_prepare_events: (0x200006f8)
[ipsp] [INF] init_app: Run IPSP sample
[ipsp] [INF] listen: Starting to wait
[bt] [ERR] le_remote_feat_complete: Unable to lookup conn for handle 32
[bt] [ERR] hci_acl: Unable to find conn for handle 32
[bt] [ERR] le_data_len_change: Unable to lookup conn for handle 32

shell>



-----Original Message-----
From: Johan Hedberg [mailto:johan.hedberg@intel.com]
Sent: Tuesday, November 21, 2017 1:03 PM
To: Vakul Garg <vakul.garg@nxp.com>
Cc: zephyr-users@lists.zephyrproject.org
Subject: Re: [Zephyr-users] Help needed to setup 6loble using IPSP sample

Hi Vakul,

On Tue, Nov 21, 2017, Vakul Garg wrote:
I am using frdm-kw41z (running hci_blackbox firmware from nxp) stacked
over frdm-k64f running zephyr sample IPSP.
In this config, frdm-kw41z acts as bluetooth controller and frdm-k64f acts
bluetooth host.

On the peer end, a linux machine is attached with another frdm-kw41z with
same hci_blackbox firmware as above (but with different BD address).

On, running 'hcitool lescan' on linux machine, it can detect the peer IPSP
node.
However, running 'hcitool lecc <ipsp node bd address>' causes following
error prints on zephyr console.

net> [bt] [ERR] hci_acl: Unable to find conn for handle 32
[bt] [ERR] le_data_len_change: Unable to lookup conn for handle 32
net> [bt] [ERR] hci_num_completed_packets: No connection for handle 32

My colleague (Maureen - thanks !!) bisected the git and found that following
commit is to blame.
Indeed, removing it solves the issue.

----------------------------------------------------------------------
---------------- commit 56f79f817e679857e385a14f9a7e9b951dbc626e
Author: Johan Hedberg
<johan.hedberg@intel.com<mailto:johan.hedberg@intel.com>>
Date: Thu Oct 5 09:43:56 2017 +0300

Bluetooth: Add support for Link Layer Privacy
----------------------------------------------------------------------
----------------

Can someone please advise me if I am missing some step or is it a bug that
needs to be logged?
The same issue causes problem with other Bluetooth examples such
peripheral_hr etc.

Have you verified that the handle value 32 is valid, i.e. the controller gave that
in a prior LE Connection Complete event? It would help investigate the issue if
you could get the entire log and also the HCI log of what's happening. It's not
clear to me how the LL Privacy patch could influence this.

Johan


Johan Hedberg
 

Hi Vakul,

On Tue, Nov 21, 2017, Vakul Garg wrote:
Have you verified that the handle value 32 is valid, i.e. the
controller gave that in a prior LE Connection Complete event?
The linux console shows up connection handle 32 has been connected.
The connection handle is completely local to the device, so what you
have on the Linux side has no relevance to Zephyr (i.e. the handles can,
and often will be different).

[bt] [ERR] le_remote_feat_complete: Unable to lookup conn for handle 32
[bt] [ERR] hci_acl: Unable to find conn for handle 32
[bt] [ERR] le_data_len_change: Unable to lookup conn for handle 32
I don't see any connection complete event in the logs prior to this. So
it's not a surprise that the host complains of an unknown handle value,
i.e. this looks like some kind of misbehavior by the controller.

Johan


Vakul Garg <vakul.garg@...>
 

-----Original Message-----
From: Johan Hedberg [mailto:johan.hedberg@intel.com]
Sent: Tuesday, November 21, 2017 1:56 PM
To: Vakul Garg <vakul.garg@nxp.com>
Cc: zephyr-users@lists.zephyrproject.org
Subject: Re: [Zephyr-users] Help needed to setup 6loble using IPSP sample

Hi Vakul,

On Tue, Nov 21, 2017, Vakul Garg wrote:
Have you verified that the handle value 32 is valid, i.e. the
controller gave that in a prior LE Connection Complete event?
The linux console shows up connection handle 32 has been connected.
The connection handle is completely local to the device, so what you have on
the Linux side has no relevance to Zephyr (i.e. the handles can, and often will
be different).

[bt] [ERR] le_remote_feat_complete: Unable to lookup conn for handle
32 [bt] [ERR] hci_acl: Unable to find conn for handle 32 [bt] [ERR]
le_data_len_change: Unable to lookup conn for handle 32
I don't see any connection complete event in the logs prior to this. So it's not a
surprise that the host complains of an unknown handle value, i.e. this looks
like some kind of misbehavior by the controller.
Can you please elaborate? On issuing 'connect' command at linux host, I get only mostly the error prints telling that connection handle can't be found.
Did my linux host even try connection establishment sequence or did it assume (say from previous run) that a certain connection already exists and tried to use it again due to which zephyr said handle does not exist?


Johan


Vakul Garg <vakul.garg@...>
 

Hi Johan

-----Original Message-----
From: Johan Hedberg [mailto:johan.hedberg@intel.com]
Sent: Tuesday, November 21, 2017 1:56 PM
To: Vakul Garg <vakul.garg@nxp.com>
Cc: zephyr-users@lists.zephyrproject.org
Subject: Re: [Zephyr-users] Help needed to setup 6loble using IPSP sample

Hi Vakul,

On Tue, Nov 21, 2017, Vakul Garg wrote:
Have you verified that the handle value 32 is valid, i.e. the
controller gave that in a prior LE Connection Complete event?
The linux console shows up connection handle 32 has been connected.
The connection handle is completely local to the device, so what you have on
the Linux side has no relevance to Zephyr (i.e. the handles can, and often will
be different).

[bt] [ERR] le_remote_feat_complete: Unable to lookup conn for handle
32 [bt] [ERR] hci_acl: Unable to find conn for handle 32 [bt] [ERR]
le_data_len_change: Unable to lookup conn for handle 32
I don't see any connection complete event in the logs prior to this. So it's not a
surprise that the host complains of an unknown handle value, i.e. this looks
like some kind of misbehavior by the controller.
My BLE controller firmware experts told me that privacy feature has some errata on my hardware.
I encountered the error even when zephyr was compiled without CONFIG_BT_PRIVACY=y.
So, I patched the hci_core.c code like this to make it work.
Can you please comment?

diff --git a/subsys/bluetooth/host/hci_core.c b/subsys/bluetooth/host/hci_core.c
index e02d5ff6a..e00ad5f37 100644
--- a/subsys/bluetooth/host/hci_core.c
+++ b/subsys/bluetooth/host/hci_core.c
@@ -3532,7 +3532,8 @@ static int le_set_event_mask(void)
mask |= BT_EVT_MASK_LE_ADVERTISING_REPORT;

if (IS_ENABLED(CONFIG_BT_CONN)) {
- if (BT_FEAT_LE_PRIVACY(bt_dev.le.features)) {
+ if (IS_ENABLED(CONFIG_BT_PRIVACY) &&
+ BT_FEAT_LE_PRIVACY(bt_dev.le.features)) {
mask |= BT_EVT_MASK_LE_ENH_CONN_COMPLETE;
} else {
mask |= BT_EVT_MASK_LE_CONN_COMPLETE;
@@ -3673,7 +3674,8 @@ static int le_init(void)
}

#if defined(CONFIG_BT_SMP)
- if (BT_FEAT_LE_PRIVACY(bt_dev.le.features)) {
+ if (IS_ENABLED(CONFIG_BT_PRIVACY) &&
+ BT_FEAT_LE_PRIVACY(bt_dev.le.features)) {
struct bt_hci_rp_le_read_rl_size *rp;
struct net_buf *rsp;




Johan


Johan Hedberg
 

Hi Vakul,

On Wed, Nov 22, 2017, Vakul Garg wrote:
My BLE controller firmware experts told me that privacy feature has some errata on my hardware.
I encountered the error even when zephyr was compiled without CONFIG_BT_PRIVACY=y.
So, I patched the hci_core.c code like this to make it work.
Can you please comment?

diff --git a/subsys/bluetooth/host/hci_core.c b/subsys/bluetooth/host/hci_core.c
index e02d5ff6a..e00ad5f37 100644
--- a/subsys/bluetooth/host/hci_core.c
+++ b/subsys/bluetooth/host/hci_core.c
@@ -3532,7 +3532,8 @@ static int le_set_event_mask(void)
mask |= BT_EVT_MASK_LE_ADVERTISING_REPORT;

if (IS_ENABLED(CONFIG_BT_CONN)) {
- if (BT_FEAT_LE_PRIVACY(bt_dev.le.features)) {
+ if (IS_ENABLED(CONFIG_BT_PRIVACY) &&
+ BT_FEAT_LE_PRIVACY(bt_dev.le.features)) {
mask |= BT_EVT_MASK_LE_ENH_CONN_COMPLETE;
} else {
mask |= BT_EVT_MASK_LE_CONN_COMPLETE;
@@ -3673,7 +3674,8 @@ static int le_init(void)
}

#if defined(CONFIG_BT_SMP)
- if (BT_FEAT_LE_PRIVACY(bt_dev.le.features)) {
+ if (IS_ENABLED(CONFIG_BT_PRIVACY) &&
+ BT_FEAT_LE_PRIVACY(bt_dev.le.features)) {
struct bt_hci_rp_le_read_rl_size *rp;
struct net_buf *rsp;
This looks like fairly reasonable fix to me. Would you be able to submit
it as a pull request? Note that there's a minor coding style issue: the
split line needs to be aligned with the first one (i.e. start right
after the opening parenthesis of the first line).

Johan


Vakul Garg <vakul.garg@...>
 

-----Original Message-----
From: Johan Hedberg [mailto:johan.hedberg@intel.com]
Sent: Wednesday, November 22, 2017 4:22 PM
To: Vakul Garg <vakul.garg@nxp.com>
Cc: zephyr-users@lists.zephyrproject.org
Subject: Re: [Zephyr-users] Help needed to setup 6loble using IPSP sample

Hi Vakul,

On Wed, Nov 22, 2017, Vakul Garg wrote:
My BLE controller firmware experts told me that privacy feature has some
errata on my hardware.
I encountered the error even when zephyr was compiled without
CONFIG_BT_PRIVACY=y.
So, I patched the hci_core.c code like this to make it work.
Can you please comment?

diff --git a/subsys/bluetooth/host/hci_core.c
b/subsys/bluetooth/host/hci_core.c
index e02d5ff6a..e00ad5f37 100644
--- a/subsys/bluetooth/host/hci_core.c
+++ b/subsys/bluetooth/host/hci_core.c
@@ -3532,7 +3532,8 @@ static int le_set_event_mask(void)
mask |= BT_EVT_MASK_LE_ADVERTISING_REPORT;

if (IS_ENABLED(CONFIG_BT_CONN)) {
- if (BT_FEAT_LE_PRIVACY(bt_dev.le.features)) {
+ if (IS_ENABLED(CONFIG_BT_PRIVACY) &&
+ BT_FEAT_LE_PRIVACY(bt_dev.le.features)) {
mask |= BT_EVT_MASK_LE_ENH_CONN_COMPLETE;
} else {
mask |= BT_EVT_MASK_LE_CONN_COMPLETE; @@
-3673,7 +3674,8 @@ static int le_init(void)
}

#if defined(CONFIG_BT_SMP)
- if (BT_FEAT_LE_PRIVACY(bt_dev.le.features)) {
+ if (IS_ENABLED(CONFIG_BT_PRIVACY) &&
+ BT_FEAT_LE_PRIVACY(bt_dev.le.features)) {
struct bt_hci_rp_le_read_rl_size *rp;
struct net_buf *rsp;
This looks like fairly reasonable fix to me. Would you be able to submit it as a
pull request? Note that there's a minor coding style issue: the split line needs
to be aligned with the first one (i.e. start right after the opening parenthesis of
the first line).
Thanks for confirming.
I am new to open source development.
I will read and find out the process of patch submission and guidelines.
So, it will take a while for me to submit the patch.
I won't mind if you submit it before I could do.


Johan