Sending large data in BLE

[Leo26781]

Hi , 

I have an Android app that acts as a Central mode and Nordic nRF9160 as peripheral mode. 

Once the connection is established , App will read the characteristics from nRF9160.  nRF9160 upon receiving the read request , responds to App with data of 140 bytes. 

As per the BLE , only 22 bytes are allowed to send . So how do i send the data ? it is like , I need to truncate the data into chunks of size 22 or will the bt_gatt_attr_read does tat ?

From the prints , I see that Android App or bt_gatt_attr_read  it self handles the truncation and sends the data. But after a while i receive "Usage fault"..

The following is the logs :

"

2020-07-30T07:41:00.620Z DEBUG modem << bt_advertise_start >>>>>>>>>
2020-07-30T07:41:02.522Z DEBUG modem << Device Connected: 46:9e:e0:b4:0c:6a (random)
2020-07-30T07:41:02.551Z DEBUG modem << Connected MTU size >>>>>> 23
2020-07-30T07:41:02.552Z DEBUG modem << MTU exchange pending
2020-07-30T07:41:03.217Z DEBUG modem << MTU exchange successful
2020-07-30T07:41:03.257Z DEBUG modem << Current MTU: 23
2020-07-30T07:41:04.046Z DEBUG modem << read start >>>>>>>>>>>>
2020-07-30T07:41:04.078Z DEBUG modem << read start string = {"id":"mIVJY7MtxcYii4Q3EeazvYsdxTCL7rUrUM8qtWaMnFCsd66KB7ljdQ42xfkK1JX0QZYbXr2Gd0+LvYiv8g==","mob":"[phone]","mp":"nRF9160DK","o":"ORG","v":2} >>>>>>>>>>>>
2020-07-30T07:41:04.080Z DEBUG modem << read start strlen() = 147 >>>>>>>>>>>>
2020-07-30T07:41:04.081Z DEBUG modem << retValue end = 22 ========================
2020-07-30T07:41:04.084Z DEBUG modem << end ========================
2020-07-30T07:41:04.118Z DEBUG modem << ***** USAGE FAULT *****
2020-07-30T07:41:04.121Z DEBUG modem << Illegal load of EXC_RETURN into PC
2020-07-30T07:41:04.122Z DEBUG modem << ***** Hardware exception *****
2020-07-30T07:41:04.125Z DEBUG modem << Current thread ID = 0x20020a48
2020-07-30T07:41:04.127Z DEBUG modem << Faulting instruction address = 0x20029374
2020-07-30T07:41:04.155Z DEBUG modem << Fatal fault in thread 0x20020a48! Aborting.
2020-07-30T07:41:04.186Z DEBUG modem << read start >>>>>>>>>>>>
2020-07-30T07:41:04.188Z DEBUG modem << read start string = {"id":"mIVJY7MtxcYii4Q3EeazvYsdxTCL7rUrUM8qtWaMnFCsd66KB7ljdQ42xfkK1JX0QZYbXr2Gd0+LvYiv8g==","mob":"[phone]","mp":"nRF9160DK","o":"ORG","v":2} >>>>>>>>>>>>
2020-07-30T07:41:04.190Z DEBUG modem << read start strlen() = 147 >>>>>>>>>>>>
2020-07-30T07:41:04.191Z DEBUG modem << retValue end = 22 ========================
2020-07-30T07:41:04.191Z DEBUG modem << end ========================
2020-07-30T07:41:04.241Z DEBUG modem << read start >>>>>>>>>>>>
2020-07-30T07:41:04.286Z DEBUG modem << read start string = {"id":"mIVJY7MtxcYii4Q3EeazvYsdxTCL7rUrUM8qtWaMnFCsd66KB7ljdQ42xfkK1JX0QZYbXr2Gd0+LvYiv8g==","mob":"[phone]","mp":"nRF9160DK","o":"ORG","v":2} >>>>>>>>>>>>
2020-07-30T07:41:04.288Z DEBUG modem << read start strlen() = 147 >>>>>>>>>>>>
2020-07-30T07:41:04.290Z DEBUG modem << retValue end = 22 ========================
2020-07-30T07:41:04.291Z DEBUG modem << end ========================
2020-07-30T07:41:04.631Z DEBUG modem << read start >>>>>>>>>>>>
2020-07-30T07:41:04.662Z DEBUG modem << read start string = {"id":"mIVJY7MtxcYii4Q3EeazvYsdxTCL7rUrUM8qtWaMnFCsd66KB7ljdQ42xfkK1JX0QZYbXr2Gd0+LvYiv8g==","mob":"[phone]","mp":"nRF9160DK","o":"ORG","v":2} >>>>>>>>>>>>
2020-07-30T07:41:04.664Z DEBUG modem << read start strlen() = 147 >>>>>>>>>>>>
2020-07-30T07:41:04.666Z DEBUG modem << retValue end = 22 ========================
2020-07-30T07:41:04.668Z DEBUG modem << end ========================
2020-07-30T07:41:04.826Z DEBUG modem << read start >>>>>>>>>>>>
2020-07-30T07:41:04.857Z DEBUG modem << read start string = {"id":"mIVJY7MtxcYii4Q3EeazvYsdxTCL7rUrUM8qtWaMnFCsd66KB7ljdQ42xfkK1JX0QZYbXr2Gd0+LvYiv8g==","mob":"[phone]","mp":"nRF9160DK","o":"ORG","v":2} >>>>>>>>>>>>
2020-07-30T07:41:04.860Z DEBUG modem << read start strlen() = 147 >>>>>>>>>>>>
2020-07-30T07:41:04.862Z DEBUG modem << retValue end = 22 ========================
2020-07-30T07:41:04.864Z DEBUG modem << end ========================
2020-07-30T07:41:05.071Z DEBUG modem << read start >>>>>>>>>>>>
2020-07-30T07:41:05.113Z DEBUG modem << read start string = {"id":"mIVJY7MtxcYii4Q3EeazvYsdxTCL7rUrUM8qtWaMnFCsd66KB7ljdQ42xfkK1JX0QZYbXr2Gd0+LvYiv8g==","mob":"[phone]","mp":"nRF9160DK","o":"ORG","v":2} >>>>>>>>>>>>
2020-07-30T07:41:05.115Z DEBUG modem << read start strlen() = 147 >>>>>>>>>>>>
2020-07-30T07:41:05.116Z DEBUG modem << retValue end = 22 ========================
2020-07-30T07:41:05.118Z DEBUG modem << end ========================
2020-07-30T07:41:05.167Z DEBUG modem << read start >>>>>>>>>>>>
2020-07-30T07:41:05.197Z DEBUG modem << read start string = {"id":"mIVJY7MtxcYii4Q3EeazvYsdxTCL7rUrUM8qtWaMnFCsd66KB7ljdQ42xfkK1JX0QZYbXr2Gd0+LvYiv8g==","mob":"[phone]","mp":"nRF9160DK","o":"ORG","v":2} >>>>>>>>>>>>
2020-07-30T07:41:05.199Z DEBUG modem << read start strlen() = 147 >>>>>>>>>>>>
2020-07-30T07:41:05.200Z DEBUG modem << retValue end = 15 ========================
2020-07-30T07:41:05.201Z DEBUG modem << end ========================
2020-07-30T07:41:05.313Z DEBUG modem << len :::1 >>>>>>>>>>>>
2020-07-30T07:41:05.339Z DEBUG modem << value :::7 >>>>>>>>>>>>
2020-07-30T07:41:05.341Z DEBUG modem << write_ct value buffer :::7 >>>>>>>>>>>>
2020-07-30T07:41:05.509Z DEBUG modem << len :::20 >>>>>>>>>>>>
2020-07-30T07:41:05.541Z DEBUG modem << value :::{"id":"3w6zaw5LlIeeOˆk >>>>>>>>>>>> write_ct value buffer :::{"id":"3w6zaw5LlIeeOSÏ–H,ì*,ŠÿÐ`)üIQP¿aWž0OÉûïg?wÓÙ$J{¼b1¥¿äÛà¸Z3“k Š”y‘žúÐ͔?÷-ȒÞ-J²Zúяòù6;îOÕ¥$¡â]Cspl{pÔÚ%ÁO·ŸŠ07€#+ >>>>>>>>>>>>
2020-07-30T07:41:06.532Z DEBUG modem << Disconnected (reason 19)
2020-07-30T07:41:50.604Z DEBUG modem << bt_advertise_stop led_tid = 537004616>>>>>>>>>
2020-07-30T07:44:50.609Z DEBUG modem << adv_thread wait for 120 secs .............
2020-07-30T07:44:50.656Z DEBUG modem << bt_advertise_start >>>>>>>>>
2020-07-30T07:45:00.833Z DEBUG modem << Device Connected: 66:45:59:e1:d6:27 (random)
2020-07-30T07:45:00.864Z DEBUG modem << Connected MTU size >>>>>> 23
2020-07-30T07:45:00.866Z DEBUG modem << MTU exchange pending
2020-07-30T07:45:00.867Z DEBUG modem << Device Connected: 66:45:59:e1:d6:27 (random)
2020-07-30T07:45:00.869Z DEBUG modem << Connected MTU size >>>>>> 23
2020-07-30T07:45:00.870Z DEBUG modem << MTU exchange pending
2020-07-30T07:45:00.871Z DEBUG modem << Device Connected: 66:45:59:e1:d6:27 (random)
2020-07-30T07:45:00.872Z DEBUG modem << Connected MTU size >>>>>> 23
2020-07-30T07:45:00.872Z DEBUG modem << MTU exchange pending
2020-07-30T07:45:00.873Z DEBUG modem << Device Connected: 66:45:59:e1:d6:27 (random)
2020-07-30T07:45:00.874Z DEBUG modem << Connected MTU size >>>>>> 23
2020-07-30T07:45:30.925Z DEBUG modem << MTU exchange failed
2020-07-30T07:45:30.976Z DEBUG modem << Exception occurred in Secure State
2020-07-30T07:45:30.977Z DEBUG modem << ***** HARD FAULT *****
2020-07-30T07:45:30.979Z DEBUG modem << Fault escalation (see below)
2020-07-30T07:45:30.981Z DEBUG modem << ***** BUS FAULT *****
2020-07-30T07:45:30.982Z DEBUG modem << Precise data bus error
2020-07-30T07:45:30.983Z DEBUG modem << BFAR Address: 0x50008120
2020-07-30T07:45:30.984Z DEBUG modem << ***** Hardware exception *****
2020-07-30T07:45:30.985Z DEBUG modem << Current thread ID = 0x20026d0c
2020-07-30T07:45:30.986Z DEBUG modem << Faulting instruction address = 0x351e0
2020-07-30T07:45:30.988Z DEBUG modem << Fatal fault in ISR! Spinning...

"

And further , I receive the "HARD FAULT "

How to resolve this ?

[Håkon Alseth]

Hi,

 

Its hard to say what is failling here, but you can try to resolve the address using "arm-none-eabi-addr2line":

arm-none-eabi-addr2line -e build/zephyr.elf 0xFAILINGADDR

 

This should give you a indication on where the fault occurred.

It seems that you are first receiving a usage-fault, then on the next reboot; a hard fault. Is the fault and address where it faults changing between each reboot?

If yes; Can you try to adjust your stack/heap size, by doubling them? via. configs CONFIG_MAIN_STACK_SIZE and CONFIG_HEAP_MEM_POOL_SIZE.

 

Kind regards,

Håkon

[Leo26781]

Hi , 

Yes I tried addr2line:

$ arm-none-eabi-addr2line.exe -e zephyr.elf 0x20020a48
D:\Workspace\nordic\ncs\nrf\samples\nrf9160\lte_ble_gateway\build_nrf9160_pca10090ns/../src/ble_peripheral.c:41

There have a k_thread declared like this:

static struct k_thread my_thread_data;

#define STACKSIZE 4096

static K_THREAD_STACK_DEFINE(threadstack,  STACKSIZE);

And I start the thread like this:

led_tid = k_thread_create(&led_thread, threadstack,
                                          K_THREAD_STACK_SIZEOF(threadstack),
                                          led_blink_thread,
                                          NULL, NULL, NULL,
                                          LED_PRIORITY, 0, K_SECONDS(7));

Not sure whether am I missing something . Also it crashes always in the same place.

BTW the heap size are as follows:

CONFIG_HEAP_MEM_POOL_SIZE=16384
CONFIG_MAIN_STACK_SIZE=8192

I guess this size is more than enough

With regards,

Leo

[Håkon Alseth]

Hi Leo,

 

But, in the first fault this is printed:

2020-07-30T07:41:04.125Z DEBUG modem << Current thread ID = 0x20020a48
2020-07-30T07:41:04.127Z DEBUG modem << Faulting instruction address = 0x20029374

This could be a overflow into that region, so it could be something that is located higher up that is actually causing the issue.

  

In the next fault, this is printed: 

2020-07-30T07:45:30.985Z DEBUG modem << Current thread ID = 0x20026d0c
2020-07-30T07:45:30.986Z DEBUG modem << Faulting instruction address = 0x351e0

Does this one tell you anything related the fault? 

Note that if you recompile or change the source in any way, the .elf file will change/reorder your addresses, so it is important that the firmware and .elf file always match each other.

 

Kind regards,

Håkon

[Leo26781]

Hi Hakon, 

In the second fault , it shows the following:

$ arm-none-eabi-addr2line.exe -e zephyr.elf 0x20026d0c
reent.c:?

And yes the everytime I change the source , I do a Clean Solution , then BUIld Solution. So I guess source and elf matches.

Also is there any way we can see the thread stack usage or something like that or debug this ?

[Håkon Alseth]

Hi,

 

This is the failing address in the second fault:

0x351e0

 

0x20026d0c is the RAM location of the thread it was executed from.

 

Kind regards,

Håkon

[Leo26781]

Hi Hakon , 

Is there any way to debug the first fault. How to debug that ? I mean stack trace or something like that ?

[Håkon Alseth]

You can check the map file (buildfolder/zephyr.map) or do an addr2line lookup there as well:

arm-none-eabi-addr2line.exe -e zephyr.elf 0x351e0

 

However; if you have recompiled, and changed the .elf file, this is likely not valid anymore. So, let it run and get the "new" faulting address and see what it shows.

 

Kind regards,

Håkon

[Leo26781]

Hi Hakon , 

I traced the second fault - 0x351be(I added some prints and the offset is changed) and it points to the following:

"

$ arm-none-eabi-addr2line.exe -e zephyr.elf 0x351be
D:/Workspace/nordic/ncs/zephyr/subsys/bluetooth/host/att.c:1960

"

In this line

"

if (conn->state != BT_CONN_CONNECTED) {

BT_WARN("Not connected");
return NULL;
}

"

BTW if we see in the above logs , it gets connected and MTU is requested. MTU request was pending , then there is multiple connect and MTU request ? 

But from Android app , they try to connect only once.

Any idea why is this behaviour ?

[Håkon Alseth]

Hi,

 

 

Leo26781 said:

In this line

Leo26781 said:

if (conn->state != BT_CONN_CONNECTED) {

This does not correspond to the att.c that is located in zephyr (ncs tag v1.2.0 or v1.3.0). Which revision of ncs are you using?

Could you share a bit more about what your application is doing (source code) ?

 

Kind regards,

Håkon

[Leo26781]

Hi , 

The following are the version , I'm using :

nrf - version - v1.0.0

[Håkon Alseth]

Hi,

 

Can you try rebasing to a newer ncs version to see if the issue still occurs there?

There has been a lot of fixes in ncs/zephyr since that release.

 

Kind regards,

Håkon

[Leo26781]

Hi , 

Yes doing that now. can you ping me the latest version. I checkout v1.3.0 now.

Is that fine ?