Mesh sample fails w/ CONFIG_BT_HCI_VS_EXT=y


Steve Brown
 

The samples/bluetooth/mesh fails on my nrf52840_pca10056

Below is the debug output of both the failing and non-failing cases.

I bisected down to:
first bad commit: [aaeff3c165051c15dfa025f1aad82f333395b6d0] 
Bluetooth: Add basic host-side support for HCI vendor extension

Somewhere CONFIG_BT_HCI_VS_EXT defaults to "y". If I set it to "n" in prj.conf, all is well.

Steve

====== failing log ============
Initializing...
[bt] [INF] hci_vs_init: HW Platform: Nordic Semiconductor (0x0002)
[bt] [INF] hci_vs_init: HW Variant: nRF52x (0x0002)
[bt] [INF] hci_vs_init: Firmware: Standard Bluetooth controller (0x00) Version 1.9 Build 99
[bt] [INF] show_dev_info: Identity: cf:f1:b8:81:59:d0 (random)
[bt] [INF] show_dev_info: HCI: version 5.0 (0x09) revision 0x0000, manufacturer 0xffff
[bt] [INF] show_dev_info: LMP: version 5.0 (0x09) subver 0xffff
Bluetooth initialized
[bt] [INF] bt_mesh_prov_init: Device UUID: 00000000-0000-0000-0000-cff1b88159d0
[bt] [DBG] bt_mesh_scan_enable: (0x20001bb8)
[bt] [DBG] adv_thread: (0x200007f8) started
[bt] [DBG] bt_mesh_proxy_adv_start: (0x200007f8)
[bt] [DBG] adv_thread: (0x200007f8) Proxy Advertising up to 60000 ms
[bt] [DBG] bt_mesh_proxy_prov_enable: (0x20001bb8)
Mesh initialized
[bt] [DBG] beacon_send: (0x20001bb8)
[bt] [DBG] unprovisioned_beacon_send: (0x20001bb8)
[bt] [DBG] bt_mesh_adv_send: (0x20001bb8) type 0x02 len 23: 00d05981b8f1cf00000000000000000000000000000000
[bt] [DBG] bt_mesh_proxy_adv_stop: (0x200007f8) adv_enabled 1
[bt] [DBG] adv_send: (0x200007f8) type 2 len 23: 00d05981b8f1cf00000000000000000000000000000000
[bt] [DBG] adv_send: (0x200007f8) count 3 interval 20ms duration 90ms
[bt] [DBG] pub_key_ready: (0x20000370) Local public key ready
ecc stack (real size 1324): unused 448 usage 876 / 1324 (66 %)
[bt] [DBG] beacon_send: (0x20001bb8)
[bt] [DBG] unprovisioned_beacon_send: (0x20001bb8)
[bt] [DBG] bt_mesh_adv_send: (0x20001bb8) type 0x02 len 23: 00d05981b8f1cf00000000000000000000000000000000
[bt] [DBG] beacon_send: (0x20001bb8)
[bt] [DBG] unprovisioned_beacon_send: (0x20001bb8)
[bt] [DBG] bt_mesh_adv_send: (0x20001bb8) type 0x02 len 23: 00d05981b8f1cf00000000000000000000000000000000
[bt] [DBG] beacon_send: (0x20001bb8)
[bt] [DBG] unprovisioned_beacon_send: (0x20001bb8)
[bt] [DBG] bt_mesh_adv_send: (0x20001bb8) type 0x02 len 23: 00d05981b8f1cf00000000000000000000000000000000
[bt] [DBG] beacon_send: (0x20001bb8)
[bt] [DBG] unprovisioned_beacon_send: (0x20001bb8)
[bt] [DBG] bt_mesh_adv_send: (0x20001bb8) type 0x02 len 23: 00d05981b8f1cf00000000000000000000000000000000
[bt] [DBG] beacon_send: (0x20001bb8)
[bt] [DBG] unprovisioned_beacon_send: (0x20001bb8)
[bt] [DBG] bt_mesh_adv_send: (0x20001bb8) type 0x02 len 23: 00d05981b8f1cf00000000000000000000000000000000
[bt] [DBG] beacon_send: (0x20001bb8)
[bt] [DBG] unprovisioned_beacon_send: (0x20001bb8)
[bt] [DBG] bt_mesh_adv_send: (0x20001bb8) type 0x02 len 23: 00d05981b8f1cf00000000000000000000000000000000
[bt] [DBG] beacon_send: (0x20001bb8)
[bt] [DBG] unprovisioned_beacon_send: (0x20001bb8)
[bt] [DBG] bt_mesh_adv_send: (0x20001bb8) type 0x02 len 23: 00d05981b8f1cf00000000000000000000000000000000
[bt] [DBG] beacon_send: (0x20001bb8)
[bt] [DBG] unprovisioned_beacon_send: (0x20001bb8)
[bt] [DBG] bt_mesh_adv_send: (0x20001bb8) type 0x02 len 23: 00d05981b8f1cf00000000000000000000000000000000
[bt] [DBG] beacon_send: (0x20001bb8)
[bt] [DBG] unprovisioned_beacon_send: (0x20001bb8)
[bt] [DBG] bt_mesh_adv_send: (0x20001bb8) type 0x02 len 23: 00d05981b8f1cf00000000000000000000000000000000
[bt] [DBG] beacon_send: (0x20001bb8)
[bt] [DBG] unprovisioned_beacon_send: (0x20001bb8)
[bt] [DBG] bt_mesh_adv_send: (0x20001bb8) type 0x02 len 23: 00d05981b8f1cf00000000000000000000000000000000
[bt] [DBG] beacon_send: (0x20001bb8)
[bt] [DBG] unprovisioned_beacon_send: (0x20001bb8)
[bt] [DBG] bt_mesh_adv_send: (0x20001bb8) type 0x02 len 23: 00d05981b8f1cf00000000000000000000000000000000
[bt] [DBG] beacon_send: (0x20001bb8)
[bt] [DBG] unprovisioned_beacon_send: (0x20001bb8)
[bt] [DBG] bt_mesh_adv_send: (0x20001bb8) type 0x02 len 23: 00d05981b8f1cf00000000000000000000000000000000
[bt] [DBG] beacon_send: (0x20001bb8)
[bt] [DBG] unprovisioned_beacon_send: (0x20001bb8)
[bt] [DBG] bt_mesh_adv_send: (0x20001bb8) type 0x02 len 23: 00d05981b8f1cf00000000000000000000000000000000
[bt] [DBG] beacon_send: (0x20001bb8)
[bt] [DBG] unprovisioned_beacon_send: (0x20001bb8)
[bt] [DBG] bt_mesh_adv_send: (0x20001bb8) type 0x02 len 23: 00d05981b8f1cf00000000000000000000000000000000
[bt] [DBG] beacon_send: (0x20001bb8)
[bt] [DBG] unprovisioned_beacon_send: (0x20001bb8)
[bt] [DBG] bt_mesh_adv_send: (0x20001bb8) type 0x02 len 23: 00d05981b8f1cf00000000000000000000000000000000
[bt] [DBG] beacon_send: (0x20001bb8)
[bt] [DBG] unprovisioned_beacon_send: (0x20001bb8)
[bt] [DBG] bt_mesh_adv_send: (0x20001bb8) type 0x02 len 23: 00d05981b8f1cf00000000000000000000000000000000
[bt] [DBG] beacon_send: (0x20001bb8)
[bt] [DBG] unprovisioned_beacon_send: (0x20001bb8)
[bt] [DBG] bt_mesh_adv_send: (0x20001bb8) type 0x02 len 23: 00d05981b8f1cf00000000000000000000000000000000
[bt] [DBG] beacon_send: (0x20001bb8)
[bt] [DBG] unprovisioned_beacon_send: (0x20001bb8)
[bt] [DBG] bt_mesh_adv_send: (0x20001bb8) type 0x02 len 23: 00d05981b8f1cf00000000000000000000000000000000
[bt] [DBG] beacon_send: (0x20001bb8)
[bt] [DBG] unprovisioned_beacon_send: (0x20001bb8)
[bt] [DBG] bt_mesh_adv_send: (0x20001bb8) type 0x02 len 23: 00d05981b8f1cf00000000000000000000000000000000
[bt] [DBG] beacon_send: (0x20001bb8)
[bt] [DBG] unprovisioned_beacon_send: (0x20001bb8)
[bt] [ERR] unprovisioned_beacon_send: Unable to allocate beacon buffer

======== successful log =============
adv stack (real size 812): unused 384 usage 428 / 812 (52 %)
Kernel stacks:
main (real size 512): unused 272 usage 240 / 512 (46 %)
idle (real size 320): unused 272 usage 48 / 320 (15 %)
interrupt (real size 2048): unused 1616 usage 432 / 2048 (21 %)
workqueue (real size 2048): unused 1704 usage 344 / 2048 (16 %)
[bt] [DBG] bt_mesh_proxy_adv_start: (0x200007f8)
[bt] [DBG] gatt_proxy_advertise: (0x200007f8)
[bt] [DBG] net_id_adv: (0x200007f8)
[bt] [DBG] net_id_adv: (0x200007f8) Advertising with NetId d47679433fdb104a
[bt] [ERR] net_id_adv: Failed to advertise using Network ID (err -5)
[bt] [DBG] adv_thread: (0x200007f8) Proxy Advertising up to -1 ms
[bt] [DBG] beacon_send: (0x20001bb8)
[bt] [DBG] secure_beacon_send: (0x20001bb8)
[bt] [DBG] bt_mesh_beacon_create: (0x20001bb8) net_idx 0x0000 flags 0x00 NetID d47679433fdb104a
[bt] [DBG] bt_mesh_beacon_create: (0x20001bb8) IV Index 0x00000005 Auth f40a41fab0af320b
[bt] [DBG] bt_mesh_adv_send: (0x20001bb8) type 0x02 len 22: 0100d47679433fdb104a00000005f40a41fab0af320b
[bt] [DBG] bt_mesh_proxy_adv_stop: (0x200007f8) adv_enabled 0
[bt] [DBG] adv_send: (0x200007f8) type 2 len 22: 0100d47679433fdb104a00000005f40a41fab0af320b
[bt] [DBG] adv_send: (0x200007f8) count 1 interval 20ms duration 30ms
[bt] [DBG] beacon_complete: (0x200007f8) err 0
[bt] [DBG] adv_send: (0x200007f8) Advertising started. Sleeping 30 ms
[bt] [DBG] adv_send: (0x200007f8) Advertising stopped
adv stack (real size 812): unused 384 usage 428 / 812 (52 %)
Kernel stacks:
main (real size 512): unused 272 usage 240 / 512 (46 %)
idle (real size 320): unused 272 usage 48 / 320 (15 %)
interrupt (real size 2048): unused 1616 usage 432 / 2048 (21 %)
workqueue (real size 2048): unused 1704 usage 344 / 2048 (16 %)
[bt] [DBG] bt_mesh_proxy_adv_start: (0x200007f8)
[bt] [DBG] gatt_proxy_advertise: (0x200007f8)
[bt] [DBG] net_id_adv: (0x200007f8)
[bt] [DBG] net_id_adv: (0x200007f8) Advertising with NetId d47679433fdb104a
[bt] [ERR] net_id_adv: Failed to advertise using Network ID (err -5)
[bt] [DBG] adv_thread: (0x200007f8) Proxy Advertising up to -1 ms
[bt] [DBG] beacon_send: (0x20001bb8)
[bt] [DBG] secure_beacon_send: (0x20001bb8)
[bt] [DBG] bt_mesh_beacon_create: (0x20001bb8) net_idx 0x0000 flags 0x00 NetID d47679433fdb104a
[bt] [DBG] bt_mesh_beacon_create: (0x20001bb8) IV Index 0x00000005 Auth f40a41fab0af320b
[bt] [DBG] bt_mesh_adv_send: (0x20001bb8) type 0x02 len 22: 0100d47679433fdb104a00000005f40a41fab0af320b
[bt] [DBG] bt_mesh_proxy_adv_stop: (0x200007f8) adv_enabled 0


Johan Hedberg
 

Hi Steve,

On Tue, Oct 17, 2017, Steve Brown wrote:
The samples/bluetooth/mesh fails on my nrf52840_pca10056

Below is the debug output of both the failing and non-failing cases.

I bisected down to:
first bad commit: [aaeff3c165051c15dfa025f1aad82f333395b6d0] 
Bluetooth: Add basic host-side support for HCI vendor extension

Somewhere CONFIG_BT_HCI_VS_EXT defaults to "y". If I set it to "n" in prj.conf, all is well.
I went through the patch in question, and found a leak of a net_buf
object. I wonder if the available buffer count has been so well
fine-tuned that loosing just one causes this issue. Anyway, could you
please try the attached patch (while keeping CONFIG_BT_HCI_VS_EXT=y).
Thanks.

Johan


Steve Brown
 

Hi John,

On Tue, 2017-10-17 at 21:08 +0300, Johan Hedberg wrote:
Hi Steve,

On Tue, Oct 17, 2017, Steve Brown wrote:
The samples/bluetooth/mesh fails on my nrf52840_pca10056

Below is the debug output of both the failing and non-failing
cases.

I bisected down to:
first bad commit: [aaeff3c165051c15dfa025f1aad82f333395b6d0] 
Bluetooth: Add basic host-side support for HCI vendor extension

Somewhere CONFIG_BT_HCI_VS_EXT defaults to "y". If I set it to "n"
in prj.conf, all is well.
I went through the patch in question, and found a leak of a net_buf
object. I wonder if the available buffer count has been so well
fine-tuned that loosing just one causes this issue. Anyway, could you
please try the attached patch (while keeping CONFIG_BT_HCI_VS_EXT=y).
Thanks.

Johan
Didn't fix it. Identical log.

Steve


Johan Hedberg
 

Hi Steve,

On Tue, Oct 17, 2017, Johan Hedberg wrote:
On Tue, Oct 17, 2017, Steve Brown wrote:
The samples/bluetooth/mesh fails on my nrf52840_pca10056

Below is the debug output of both the failing and non-failing cases.

I bisected down to:
first bad commit: [aaeff3c165051c15dfa025f1aad82f333395b6d0] 
Bluetooth: Add basic host-side support for HCI vendor extension

Somewhere CONFIG_BT_HCI_VS_EXT defaults to "y". If I set it to "n" in prj.conf, all is well.
I went through the patch in question, and found a leak of a net_buf
object. I wonder if the available buffer count has been so well
fine-tuned that loosing just one causes this issue. Anyway, could you
please try the attached patch (while keeping CONFIG_BT_HCI_VS_EXT=y).
Thanks.
Here's version 2. The first attempt didn't take the account the jump to
a label in the success case. So ignore the earlier and test this one,
please.

Johan


Steve Brown
 

Hi Johan,

On Tue, 2017-10-17 at 21:08 +0300, Johan Hedberg wrote:
Hi Steve,

On Tue, Oct 17, 2017, Steve Brown wrote:
The samples/bluetooth/mesh fails on my nrf52840_pca10056

Below is the debug output of both the failing and non-failing
cases.

I bisected down to:
first bad commit: [aaeff3c165051c15dfa025f1aad82f333395b6d0] 
Bluetooth: Add basic host-side support for HCI vendor extension

Somewhere CONFIG_BT_HCI_VS_EXT defaults to "y". If I set it to "n"
in prj.conf, all is well.
I went through the patch in question, and found a leak of a net_buf
object. I wonder if the available buffer count has been so well
fine-tuned that loosing just one causes this issue. Anyway, could you
please try the attached patch (while keeping CONFIG_BT_HCI_VS_EXT=y).
Thanks.

Johan
More ...

In looking at the log, it appears that the beacon_complete callback
never gets called from bt_mesh_adv_send. So, net_buf_unref never gets
called and we run out of buffers.

Steve


Steve Brown
 

On Tue, 2017-10-17 at 21:23 +0300, Johan Hedberg wrote:
Hi Steve,

On Tue, Oct 17, 2017, Johan Hedberg wrote:
On Tue, Oct 17, 2017, Steve Brown wrote:
The samples/bluetooth/mesh fails on my nrf52840_pca10056

Below is the debug output of both the failing and non-failing
cases.

I bisected down to:
first bad commit: [aaeff3c165051c15dfa025f1aad82f333395b6d0] 
Bluetooth: Add basic host-side support for HCI vendor extension

Somewhere CONFIG_BT_HCI_VS_EXT defaults to "y". If I set it to
"n" in prj.conf, all is well.
I went through the patch in question, and found a leak of a net_buf
object. I wonder if the available buffer count has been so well
fine-tuned that loosing just one causes this issue. Anyway, could
you
please try the attached patch (while keeping
CONFIG_BT_HCI_VS_EXT=y).
Thanks.
Here's version 2. The first attempt didn't take the account the jump
to
a label in the success case. So ignore the earlier and test this one,
please.

Johan
This patch fixed it.

Thanks,

Steve


Johan Hedberg
 

Hi Steve,

On Tue, Oct 17, 2017, Steve Brown wrote:
More ...

In looking at the log, it appears that the beacon_complete callback
never gets called from bt_mesh_adv_send. So, net_buf_unref never gets
called and we run out of buffers.
It's still a mystery how that's related to the patch you found with
bisect. Did you try the v2 of my patch? The first version will not make
any difference to you since it had the missing unref in a branch that's
never taken in your case.

Johan


Steve Brown
 

Hi Johan,

On Tue, 2017-10-17 at 21:39 +0300, Johan Hedberg wrote:
Hi Steve,

On Tue, Oct 17, 2017, Steve Brown wrote:
More ...

In looking at the log, it appears that the beacon_complete callback
never gets called from bt_mesh_adv_send. So, net_buf_unref never
gets
called and we run out of buffers.
It's still a mystery how that's related to the patch you found with
bisect. Did you try the v2 of my patch? The first version will not
make
any difference to you since it had the missing unref in a branch
that's
never taken in your case.

Johan
I looked at the recent commits and didn't see any connection either.That's why I gave up and did the bisect.

Is it possible that because the buffer wasn't released, subsequent
commands queued up and eventually used up all available buffers?

Steve