This post is older than 2 years and might not be relevant anymore
More Info: Consider searching for newer posts

connectivity_bridge malfunctions when BLE client disconnects and reconnects

I noticed that when a BLE client disconnects and then reconnects to the, instead of receiving all data arriving over the UART from nRF9160 to nRF52840, there is a delay of several seconds after which a huge block of 2048 bytes is sent over to the BLE client. This size matches the BRIDGE_BUF_SIZE configuration. The issue is observed on both Thingy:91 using the sample provided as part of the precompiled firmware, and also on nRF9160 DK - I ported the sample to work on it, so I observe the same behaviour on both boards. I tried changing BRIDGE_BUF_SIZE, and since I observed that internally 182 bytes are used for BLE transmission, I used that value. Now parts of the NMEA data sent from the GPS sample is randomly scrambled, resulting in 40% or NMEA packets that fail basic validation and CRC.

This attached log has been recorded from nRF9160dk, using the modified connectivity_bridge, which I adapted to run on the DK.
The GPS sample has also been modified, so send a copy of the NMEA strings to its second UART, which on the modified board links to the nRF52840 chip and is forwarded to BLE (application) and USB (this log file).

The following changes have been made:
nrf/samples/nrf9160/gps/src/main.c
static void print_nmea_data(void)
{
for (int i = 0; i < nmea_string_cnt; ++i) {
printk("%s", nmea_strings[i]);
+
+ #if CONFIG_TRACING_TEST
+ TRACING_STRING("%s", nmea_strings[i]);
+ #endif
+
+ #if CONFIG_UART_BLE
+ int uart_ble_send(char * msg, uint16_t length);
+ uart_ble_send(nmea_strings[i], strlen(nmea_strings[i]));
+ #endif
}
}

nrf/applications/connectivity_bridge.nrf9160dk/src/modules/Kconfig
BRIDGE_BUF_SIZE=182

nrf/applications/connectivity_bridge.nrf9160dk/prj.conf
CONFIG_USB_DEVICE_PRODUCT="nrf9160dk UART"

Send a copy of the data being sent to BLE over the debug UART of nRF52840. The USB on nRF9160dk connects to an OpenWRT router which acts as a mobile UART to TCP bridge and is then recorded on a computer using netcat.

nrf/applications/connectivity_bridge_g/src/modules/ble_handler.c
static void bt_send_work_handler(struct k_work *work)
{
uint16_t len;
uint8_t *buf;
int err;
bool notif_disabled = false;

do {
len = ring_buf_get_claim(&ble_tx_ring_buf, &buf, nus_max_send_len);

err = bt_gatt_nus_send(current_conn, buf, len);
if (err == -EINVAL) {
notif_disabled = true;
len = 0;
} else if (err) {
len = 0;
}

+ if (len)
+ {
+ char msg[BLE_TX_BUF_SIZE];
+ memcpy(msg, buf, len);
+ msg[len] = '\0';
+ printk("%s", msg);
+ }


err = ring_buf_get_finish(&ble_tx_ring_buf, len);
if (err) {
LOG_ERR("ring_buf_get_finish: %d", err);
break;
}
} while (len != 0 && !ring_buf_is_empty(&ble_tx_ring_buf));

if (notif_disabled) {
/* Peer has not enabled notifications: don't accumulate data */
ring_buf_reset(&ble_tx_ring_buf);
}
}

The following line is not valid:
$GPGLL,4.31375,N,02445.01620,E,1,04,100.00,312.72,M,0,,*26

Both of the following lines have a valid checksum:
* the first line contains invalid data
* the second line is valid
$GPGGA,085500.23,4208.30949,N,02444.97N,02444.9766.16,217.38,M,0,,*23
$GPGGA,085500.23,4208.30949,N,02444.97660,E,1,10,1.16,217.38,M,0,,*23

Notice how a part of the packet is missing or replaced with data, from
another packet. 40% of the packets are discarded, because they:
* do not begin with $
* do not have * in position line_length - 3
* do not have a valid checksum

From the the remaining 60% of the packets which pass the above validation,
a few are discarded because they:
* have values out of range
* have missing or more than one . character in a float value
* have less or more characters per line of value than expected

In rare events, there are still packets that pass all validation, but
contain slightly invalid data, e.g. there could be a long spike on the map
when our application is drawing the path.

If BRIDGE_BUF_SIZE is reverted to its default value of 2048,
Once the BLE client disconnects and then reconnects, the connectivity bridge
starts working incorrectly and will send large blocks of 2048 bytes containg
multiple NMEA packets.

ble_handler.test.c is my attempt to add tracing code and investigate what
is wrong with the connectivity_bridge. It seems that the ble_handler is holding
all buffers, so the uart_handler has no space to store arriving data.
At some point the buffers are freed by BLE, but then UART sends another 2048 bytes
of data, which arrave at bt_send_work_handler(). It starts sending blocks of
nus_max_send_len=182 until the BLE driver chokes. At this point BLE transmission
stalls for a few seconds, and UART RX will drop some data. Next the process repeats.
I am sorry for not being able to provid more details, and this parragraph may not be
fully accurate, because the code is extremely hard to follow.

I need to make one very important note towards the Nordic SDK developers:
Please make things simple and reliable!
I cannot say if the above issue is due to the existing design patterns in Zephyr OS,
but I see that all design patters are extremely complex and hard to follow, even
for taks that are very simple to implement, such as read/write from UART or BLE,
I see that you write 400 lines of code for each!
Hence it comes to no surprise that such a complex code has bugs which are hard to
diagnose or resolve. For example, as part of my testing I needed to change the
gps sample for nRF9160dk, so that in addition to its normal output, it sends a copy
with only the NMEA strings to its second UART, which I routed to the nRF52840 chip to
forward over BLE. My expectation was that I can simply write the data to UART.
But instead of a one line solution, I was forced to dedicate 330 lines of code:
zephyr/boards/arm/nrf9160dk_nrf9160_g/uart_ble.c
with a lot of handling routines and thigs that should normally be handled by
the driver, and any decent operating system provides a simple to use interface.

Using Nordic SDK master

nrf
commit ecf5d334f1577cc7fca11ae7b5a7fb86f0ea757a

zephyr
commit 7d20f2ebf25991b2897b91275939f8d16d38513a

 4572.projects.7z

Parents
  • What tag/commit are you working on? There has been some work on the connectivity_bridge application recently that should improve its stability, could you check out the master branch or NCS v1.4.0 rc1 and see if your problems goes away? These are the commits that is of interest to you:

    If this doesn't solve your problems, please tell me and I'll investigate it more deeply, try to reproduce it and see if I can get to the bottom of it.

    Best regards,

    Simon

  • Hello Simon!

    I updated to nrf e0d62535662ed6e04730b53f5c7b92fa58cedabf, and zephyr 105a1b9e2bc48acdd1f1173ad2ef43a90c120fbe. The connectivity bridge seems to work better, and at first I thought the issue had been resolved, but after leaving my Thingy:91 to recharge during the night, in the morning I discovered that all symptoms have reappeared. I am currently using the default configuration with buffers of 2048 bytes. My iPhone application receives large packets probably of size 2048 with a long delay between each packet. Around 3% of the packets are invalid, which is way less than 40%, but that's probably because the buffer size is 2048 bytes instead of 182 bytes.

    I am sorry for the late replay. Every time I have to update the SDK, I have to adapt my environment on two computers: Visual Studio projects, macros, paths… It's a lot of work. Then I have to port my projects and test all of them to make sure they work correctly. So as you can see, it's a very time consuming process. And due to the many bugs in the SDK, I spend more time in updates then I do in development and productivity work.

    Speaking of bugs, there is another bug in the GPS. After using the nRF9160DK for a few days the GPS demo stops updating and keeps sending the same values and timestamp over and over again:

    $GPGGA,174132.86,,,,,0,,99.99,,M,0,,*3B
    $GPGLL,,,,,174132.86,V,A*49
    $GPGSA,A,1,,,,,,,,,,,,,99.99,99.99,99.99,1*2D
    $GPGSV,1,1,0,,,,,,,,,,,,,,,,,1*54
    $GPRMC,174132.86,V,,,,,,,271020,,,N,V*0D
    $GPGGA,174132.86,,,,,0,,99.99,,M,0,,*3B
    $GPGLL,,,,,174132.86,V,A*49
    $GPGSA,A,1,,,,,,,,,,,,,99.99,99.99,99.99,1*2D
    $GPGSV,1,1,0,,,,,,,,,,,,,,,,,1*54
    $GPRMC,174132.86,V,,,,,,,271020,,,N,V*0D
    $GPGGA,174132.86,,,,,0,,99.99,,M,0,,*3B
    $GPGLL,,,,,174132.86,V,A*49
    $GPGSA,A,1,,,,,,,,,,,,,99.99,99.99,99.99,1*2D
    $GPGSV,1,1,0,,,,,,,,,,,,,,,,,1*54
    $GPRMC,174132.86,V,,,,,,,271020,,,N,V*0D
    $GPGGA,174132.86,,,,,0,,99.99,,M,0,,*3B
    $GPGLL,,,,,174132.86,V,A*49
    $GPGSA,A,1,,,,,,,,,,,,,99.99,99.99,99.99,1*2D
    $GPGSV,1,1,0,,,,,,,,,,,,,,,,,1*54
    $GPRMC,174132.86,V,,,,,,,271020,,,N,V*0D

    During this time I had been working only with the nRF52840 chip. At some point I noticed that I'm receiving the same NMEA data over and over again. After powering off the board or resetting the nRF9160 chip, the data starts updating again for a few days, and then I start getting the same data repeatedly. This looks rather like a firmware issue.

    I'm not sure if I should blame Zephyr or Nordic, but the Nordic SDK is a very unreliable platform. I'm very unproductive building on top of it. This is in huge part because of me, since I am new to this platform, yet also because in order to learn a new platform one has to experiment with working examples and see how things are accomplished. Sadly although there are a lot of good things in the SDK that should make tasks simple, your team has a long road to go, in order to make it a reliable platform. I hope to see the quality improved soon!

    Since reliable grounds are a necessity in order to advance with my work, I ported our own RTOS − Euros on the nRF52840 CPU. So far this has been a very easy process. Let me know if your team is interested in a robust UART driver that can be used bare metal or integrated with any OS. DMA, interrupts, sync and async modes are fully supported. Unlike what is offered by Zephyr, the interface is very simple to use. When send and recv API is used by a task, if a wait is required, the task is put to sleep freeing CPU cycles for other tasks. The API can also run on bare metal, with interrupts disabled or within fault handlers. It just works and is very simple to use. There is only one restriction: it is not currently free software, but we can license it.

  • I am using the modified version of connectivity bridge with my UART driver to eliminate the buggy UART driver from Nordic:

    connectivity_bridge_thingy.7z

  • If I set a breakpoint in the beginning of sdc_assertion_handler, I get file = r0 = 0x2001c6f0 = "62", line = r1 = 1865. I thought we are supposed to get an absolute file path here? And why does the call stack contain hashed symbols? How can I unwind and debug this situation?

  • I'm really sorry, but I forgot to ask you about the content inside the file pointer as well. If it's much work to you, I can set it up myself and get it.

    You could also set CONFIG_BT_DEBUG_LOG=y and CONFIG_BT_DEBUG_HCI_DRIVER=y and provide the output of the following log:

    BT_ERR("SoftDevice Controller ASSERT: %s, %d", log_strdup(file), line);

    Then you can see both the file and the line the assert happens on, and I can forward it to the SoftDevice team

    Best regards,

    Simon

  • I added the two lines you requested to connectivity_bridge_thingy/prj.conf, then deleted the build directory, and restarted Segger Embedded Studio, opened the project, and rebuilt the solution. It still shows file = "62", and there is no output generated from the BT_ERR line. Attached bellow is the project with the build directory generated on macOS. Did I edit prj.conf correctly or should I put these changes somewhere else?

    connectivity_bridge_thingy.tgz

  • Hmm.. I'll try to reproduce this myself tomorrow and see if I'm able to get more information out.

    This ticket is quite long. Could you open a new ticket and link to it here? Then we can continue from there.

    Georgi Valkov said:
    And why does the call stack contain hashed symbols? How can I unwind and debug this situation?

    I suspect you're not getting any more information because the SoftDevice Controller is not open source, as explained here: https://devzone.nordicsemi.com/f/nordic-q-a/78019/the-difference-between-the-two-controllers-on-nrf-connect-sdk/322586#322586 

Reply Children
  • I think file="62" and line=1865 should be enough to get information about the assert. I have forwarded this internally and I'm waiting for an answer. I'll keep you updated.

  • The assert means that the SoftDevice is not able to set up the Radio.

    I got some suggestions:

    "Hi, Does the customer enable FEM and/or disable interrupts?"

    "You could ask about coex as well. I think these three would be the most likely ones."

    Could you check what is the case for you?

    My suspicion is that the assert is caused by disabling of interrupts. You can read more about this in this ticket (where the nRF5 SDK+SoftDevice is used):

    https://devzone.nordicsemi.com/f/nordic-q-a/17199/disable-interrupt-for-about-3-cycle/66068#66068

  • Hello Simon!

    You know I actually wanted to open this question earlier: I noticed that when BLE is enabled in connectivity bridge, nRF52840 reboots as soon as I try stepping into the debugger. I'm not sure why the BLE code has housekeeping timers that need to do this, but I would call this a very bad design and experience. It is practically impossible to debug code on this CPU using the jTAG.

    So regarding the question asked by your colleagues: Yes, since I replaced the Nordic driver with my own UART miniport driver, this needs to disable interrupts for a very short time. In the worst case a maximum of 256 bytes need to be copied from driver's DMA buffer to user region, which should not take more than a few microseconds I guess, it should not be much of a concern. I could try disabling only the UART interrupt instead of doing it globally. But your team should definitely improve their design too. As I said, it is not possible to debug code on this CPU. The entire deign is just asking for something wrong to happen, and from what I can see from your link, other people also face design limitations, which make using Nordic products less suitable for their task. I should also note that the changes made by Nordic in v1.8.0 made it crash much more often than v1.7.1. I also do not recall any crash with older versions of the SDK.

    What is FEM? What is coex? What is the BLE designed is such a way that disabling interrupts could trigger an assert? What is the SoftDevice and why is it closed source? Does this mean that BLE on Nordic boards can only be used with Zephyr?

    devzone.nordicsemi.com/.../281686

  • Thanks for opening a new ticket. Let's continue the discussion there. I'll get back to you tomorrow.

Related