CONFIG_BT_HCI_TX_STACK_SIZE is too small

[pdunaj]

Describe the bug
I have pca10059 configured as central (running ncs nrf_desktop). The device crashes during connection attempt with a peripheral.
CONFIG_BT_HCI_TX_STACK_SIZE is set to 640B in Zephyr. If extend it to 1024B program works (I have not tried lower values yet).

We have not seen it in the past. The thing is that due to recent bugs we have MPU stack guard enabled by default now.

To Reproduce
Steps to reproduce the behavior:
Build nrf_desktop for pca10059 and try to connect to peripheral (DK working as mouse from the same project should work).
Try to connect and observe crash.

Expected behavior
Should not crash.

Impact
Showstopper.

Screenshots or console output

[00000204] <inf> ble_scan: Scan started
--
[00000213] <inf> event_manager: e: usb_state_event id:0x200000a9 state:POWERED
[00008655] <inf> ble_scan: Filters matched. fd:a0:61:de:7d:07 (random) connectable
[00008679] <inf> ble_scan: Connecting done
[00009066] <inf> usb_state: USB HID enabled
[00009069] <inf> event_manager: e: usb_state_event id:0x200000a9 state:ACTIVE
[00009072] <inf> event_manager: e: hid_report_subscription_event MOUSE report notification enabled by 0x200000a9
[00009944] <wrn> usb_hid: len 143 doesn't match Report Descriptor size
[00012038] <inf> ble_state: Connected to fd:a0:61:de:7d:07 (random)
[00012044] <wrn> bt_ctlr_hci: handle: 0x0000, CSA: 1.
[00039955] <inf> ble_state: Security with fd:a0:61:de:7d:07 (random) level 2
[00039959] <inf> event_manager: e: ble_peer_event id=0x2000227c SECURED
***** MPU FAULT *****
Stacking error
Data Access Violation
MMFAR Address: 0x20006e98
***** Hardware exception *****
Current thread ID = 0x200021f0
Faulting instruction address = 0x2aa7c
Fatal fault in thread 0x200021f0! Aborting.
[ASSERTION FAIL [out_ctx->control_block->offset <= out_ctx->size] @ /home/pdunaj/work/ncs/zephyr/subsys/logging/log_output.c:101

Environment (please complete the following information):
rev: a76f833 (ncs) from ec424b7 (zephyr)

Additional context
N/A

[pdunaj]

I am wondering if callbacks informing about connection/filter status/etc. are called from this thread.

[jhedberg]

The definition is actually as follows:

config BT_HCI_TX_STACK_SIZE                                                     
        int                                                                     
        default 512 if BT_H4                                                    
        default 512 if BT_H5                                                    
        default 416 if BT_SPI                                                   
        default 940 if BT_CTLR && NO_OPTIMIZATIONS                              
        default 640 if BT_CTLR                                                  
        default 512 if BT_USERCHAN                                              
        # Even if no driver is selected the following default is still          
        # needed e.g. for unit tests.                                           
        default 512

So I suppose it's the if BT_CTLR line(s) that you want to modify

[carlescufi]

@pdunaj can you please send a PR so that you set a reasonable value based on your measurements?

[pdunaj]

Hi @carlescufi , sure. Will look for something sensible tomorrow and check if any callback can affect it.

Hi @jhedberg, I actually prefer to increase it only when BT_CENTRAL is enabled. We don't seem to see any problem on the peripheral side.

[jhedberg]

Btw, if the BT_CTLR && NO_OPTIMIZATIONS value ends up being close to the BT_CTLR one I'd just merge these to a single one (like it used to be in the past)

[jhedberg]

Hi @jhedberg, I actually prefer to increase it only when BT_CENTRAL is enabled. We don't seem to see any problem on the peripheral side.

@pdunaj It'd be good to understand the root cause first. The reason this Kconfig option is not settable by the application is that the assumption has been that the app can't influence this stack's usage. Now it sounds like this might not be true, in which case we might want to revisit making this settable by the application.

[jhedberg]

@pdunaj or do you mean that simply enabling BT_CENTRAL increases it (i.e. doesn't depend on the app doing central-related actions at runtime)? Meaning, something in the controller-side TX code-path changes when BT_CENTRAL is set? In that case it'd be justified to put the necessary logic in Kconfig (not that I'm particularly happy about the level of complexity this is growing to)

[pdunaj]

@jhedberg I mean adding a line default xyz if BT_CTLR && BT_CENTRAL to the Kconfig. I prefer not to extend RAM usage as we are tight on it. Soon I will look for 2-3kB to be freed in BLE host btw so increasing it anywhere is not a good idea.

First I plan to check if any callback can be called from this function. I guess not as I expect rx side to handle it. Still I don't know this stack so I will have to have a look.

[pdunaj]

0x20002D94 BT RX      (real size 2016): unused 1096     usage 920 / 2016 (45 %)
0x20002D0C BT RX pri  (real size 608):  unused 32       usage 576 / 608 (94 %)
0x200023F4 BT ECC     (real size 1068): unused 104      usage 964 / 1068 (90 %)
0x200024DC BT TX      (real size 992):  unused 96       usage 896 / 992 (90 %)
0x200041C0 sysworkq   (real size 992):  unused 128      usage 864 / 992 (87 %)
0x200017E4 shell_rtt  (real size 2016): unused 816      usage 1200 / 2016 (59 %)
0x200013F0 logging    (real size 992):  unused 760      usage 232 / 992 (23 %)
0x20003C24 idle       (real size 96):   unused 40       usage 56 / 96 (58 %)
prio recv thread stack (real size 640): unused 32       usage 608 / 640 (95 %)
recv thread stack (real size 2048):     unused 1096     usage 952 / 2048 (46 %)

The kernel stacks information is above. It seems that tx stack set to 1024 is actually not too big.

When I enabled shell I also got fault on PRI RX stack. I expanded this one to 640 and it also is not too big it seems.

So it seems that the problem may be caused by increased RAM consumption cause by log messages.

[pdunaj]

I have also tried to see why we have this logs enabled as we select BT_DEBUG_NONE... and found out that BT_DEBUG is being selected by ncs's discovery manager's option BT_GATT_DM_DATA_PRINT. If anything this option should depend on !BT_DEBUG_NONE being selected (any level except none) which actually would be depending on BT_DEBUG. @kapi-no

I will add a change to NCS and see if stack problems are gone if debugs are disabled.

There is still however an open question of how to expand this stacks - if debugs are enabled these will be too small and crash will occur. We have stack guard but unless somebody has it too they will not notice stack overflow. I think we should expand the stacks anyway but depend on BT_DEBUG option being set.