SoftDevice Controller ASSERT: 53, 296

[Maos]

Hi!

Can you please help me identify what is causing this issue and/or provide more info about this:

[00:04:23.038,330] \033[1;31m<err> bt_sdc_hci_driver: SoftDevice Controller ASSERT: 53, 296\033[0m
[00:04:57.431,335] \033[1;31m<err> os: ***** HARD FAULT *****\033[0m
[00:04:57.431,335] \033[1;31m<err> os:   Fault escalation (see below)\033[0m
[00:04:57.431,365] \033[1;31m<err> os: ARCH_EXCEPT with reason 3
\033[0m
[00:04:57.431,365] \033[1;31m<err> os: r0/a1:  0x00000003  r1/a2:  0x00000000  r2/a3:  0x0001981b\033[0m
[00:04:57.431,396] \033[1;31m<err> os: r3/a4:  0x00000000 r12/ip:  0x20000ab0 r14/lr:  0xffffffff\033[0m
[00:04:57.431,396] \033[1;31m<err> os:  xpsr:  0x41000011\033[0m
[00:04:57.431,396] \033[1;31m<err> os: r4/v1:  0x20015c70  r5/v2:  0x0003370d  r6/v3:  0x0000000a\033[0m
[00:04:57.431,427] \033[1;31m<err> os: r7/v4:  0x20015c70  r8/v5:  0x20001944  r9/v6:  0x2000e204\033[0m
[00:04:57.431,427] \033[1;31m<err> os: r10/v7: 0x200008bc  r11/v8: 0x00000000    psp:  0x20015f40\033[0m
[00:04:57.431,457] \033[1;31m<err> os: EXC_RETURN: 0xfffffff1\033[0m
[00:04:57.431,457] \033[1;31m<err> os: Faulting instruction address (r15/pc): 0x00033744\033[0m
[00:04:57.431,488] \033[1;31m<err> os: >>> ZEPHYR FATAL ERROR 3: Kernel oops on CPU 0\033[0m
[00:04:57.431,518] \033[1;31m<err> os: Fault during interrupt handling
\033[0m
[00:04:57.431,549] \033[1;31m<err> os: Current thread: 0x2000ae30 (unknown)\033[0m
[00:05:09.972,747] \033[1;31m<err> fatal_error: Resetting system\033[0m

When this happens it is in the process of uploading a new fw thru mcumgr image group, upload command.

I haven't been able to fully verify this but I think this affected by updating to SDK 2.6.0 (from 2.4.0).
That code part is unchanged before and after the SDK update except that "zcbor_new_decode_state" had two new parameter which we have set to NULL and 0 (after comparing how some examples had changed between sdk versions).

BR,
Mårten

[Maos]

Hi!

I have tried various settings to get a lead what could be causing this without much luck.

Regarding threads this is the status of them at the time the exception happens:

And this is the callstack:


I don't know if they provide any new lead on what is causing this.

I have tested this with the v2,4 and v2.6 stack and I can't reproduce it on the v2.4 stack (only code change during the test is three locations where we call zcbor_new_decode_state).

I have doing various adjustments to our thread priorites and also tested to enable CONFIG_BT_RECV_WORKQ_BT.

I tried to see if there where any interesting configs related to irq priorites but I couldn't find a working combination of settings (Mostly NFCT_IRQ_PRIORITY and ZERO_LATENCY_LEVELS).

(The device receive and send data on NFC but I don't need to blipp it to make this issue happen).

But none of these changes seem to solve the issue.

BR,

Mårten

[Einar Thorsrud]

Hi Mårten,

I checked with our SoftDevice Controller team and they did not have any more specific ideas other than wondering if you (or a module you use) perhaps disables interrupts for too long (as in a critical section with irq_lock()/irq_unlock(). Could that be the case?

Br,

Einar

[Maos]

Hi!

Well we use the uart, nfc and bluetooth of the device and in the case of bluetooth scan for advertise data and if needed connect to the peripherial to either write a fairly small amount of data and/or do a OTA.
We only allow one connection doing OTA and one other in parallel.

I have also tried sdk version 2.5.3 and 2.6.0-rc1 and am not able to reproduce the issue on 2.5.3 but can reproduce it on 2.6.0-rc1.

I have tried to look over our code to see if there is some processing that is done when parsing the advertise data that should be deffered to later in some way, this does not seem to help the issue.

At the moment I am actually looking into the uart sending part.
The uart sending is done by copying the data to one buffer taken from a pool of buffers and put in a fifo that is read by a seperate thread that calls the uart tx function.

I did some test basically disabling the whole tx part (after some initial setup communication) and could not reproduce the issue.
At that test it looked like lowering the priority of the uart-tx-thread did not help.

I also noticed that by mistake the item put in the fifo was not (explicitly) word aligned, thou it probably would be because the second item in the struct after the intial (reserved) word was for some reason set to alignment 16.

So at the moment I am looking into moving the "disabling" of tx from the entry point to the thread to see how that affects reproducability and if setting the alignment correctly will make a difference, possibly in combination with lowering the tx thread prio.

This in one way feels a bit far fetched but this is the only change that seem to affect reproducability....

BR,
Mårten

[Einar Thorsrud]

Hi Mårten,

It is good to hear you are making progress in narrowing down the issue. I do not have any suggestions from our side at the moment, but please let me know if you are able to narrow this down futher.

Br,

Einar

[Maos]

Hi

Seems the uart thing was false lead (maybe not so suprising), it might have probability of reproducing somewhat.

Also noticed I had commented out code that initialize nfc at the same time..

I did try to lower irq priority of both uart and nfc in device tree, couldn't find any clear information on this but hoped that a higher number meant lower priority but the assert was still triggered.

One detail I forgot to mention is that it onlly seem to happen if the peripheral is a bit away from the central, the rssi value reported by the SDK is somewhere betwen -85 and -95 when it happens.

Most of the time when this issue happens the connection has been lost once and then been able to reconnect again, and during this second connection this assert kicks in.

I think I have seen this on "first" connection but maybe it has been connected and done a "proper" disconnect but I missed to reset the test setup, so it is still on second connection.

I also noticed a place where the same connection maybe is disconnected twice (so disconnect returns -128).

I also tried with the 2.7.0-rc2 SDK and get a bit different ASSERT:
00> [00:00:38.858,306] [1;31m<err> bt_sdc_hci_driver: SoftDevice Controller ASSERT: 53, 345[0m
00> [00:00:38.858,337] [1;31m<err> os: ***** HARD FAULT *****
00> [00:00:38.858,337] [1;31m<err> os:   Fault escalation (see below)[0m
00> [00:00:38.858,367] [1;31m<err> os: ARCH_EXCEPT with reason 3
00>  
00> [00:00:38.858,367] [1;31m<err> os: r0/a1:  0x00000003  r1/a2:  0x00000000  r2/a3:  0x000e7241
00> [00:00:38.858,367] [1;31m<err> os: r3/a4:  0x00000003 r12/ip:  0x2001a238 r14/lr:  0xffffffff
00>  
00> [00:00:38.858,398] [1;31m<err> os:  xpsr:  0x01000011
00> [00:00:38.858,398] [1;31m<err> os: r4/v1:  0x20018168  r5/v2:  0x00033db9  r6/v3:  0x0000000a[0m
00>  
00> [00:00:38.858,428] [1;31m<err> os: r7/v4:  0x20018168  r8/v5:  0x00000000  r9/v6:  0x00000000[0m
00> [00:00:38.858,428] [1;31m<err> os: r10/v7: 0x200009a0  r11/v8: 0x00000000    psp:  0x20018480
00> [00:00:38.858,459] [1;31m<err> os: EXC_RETURN: 0xfffffff1[0m
00> [00:00:38.858,459] [1;31m<err> os: Faulting instruction address (r15/pc): 0x00033df4[0m
00> [00:00:38.858,489] [1;31m<err> os: >>> ZEPHYR FATAL ERROR 3: Kernel oops on CPU 0[0m
00> [00:00:38.858,489] [1;31m<err> os: Fault during interrupt handling
00>  
00>  
00> [00:00:38.858,551] [1;31m<err> os: Current thread: 0x2000bd80 (unknown)[0m
00> [00:00:51.399,688] [1;31m<err> os: Halting system[0m


What can be interpreted from this one?

Also could the callback passed to bt_dfu_smp_command block the softdevice (assuming there is no explicit call to irq_lock or similar)?

BR,

Mårten