The nRF Connect SDK for desktop (python) is very slow to discover characteristics at time and very flaky in whether it hangs up midway or not. CAn anyone help me out with my softdevice logic?

[Yatekii]

Hi,

As I mentioned in the title, I am using the `pc-ble-driver-py` python package which is basically bindings to the SoftDevice running on the nRF52840 dongle.

Here is my complete code:

https://gist.github.com/Yatekii/9dcedf0224a05ab846b2786c2c275aaf

The issue is here on line 27:

https://gist.github.com/Yatekii/9dcedf0224a05ab846b2786c2c275aaf#file-run-py-L27

This .connect() method takes > 3 seconds to discover all services. The connecttion is established within milliseconds, but the discovery goes on way too long. This to 3 seconds too long! When I use the nRF Connect Desktop app written in Node.js it is < 1s and the same if I use bluez.

Since this is for our production testing, I need this to be way below 1 second! Imagine doing this for 100k devices. That's a lot of time =)

What's more is that it sometimes never connects at all without further output. Then the process just hangs and I have to kill it. When that happens it looks like this:

2.1457672119140625e-06: Start
Received advertisment report, address: C0:58:FA:AA:28:8C, device_name: zigfred
0.11480927467346191: Found zigfred
0.0011899471282958984: Stopped scan
Heading to discovery
New connection: 0
{'status': <BLEGattStatusCode.success: 0>, 'services': [<pc_ble_driver_py.ble_driver.BLEService object at 0x7f15aceadd60>]}
{'status': <BLEGattStatusCode.attribute_not_found: 266>, 'services': []}
0.35233449935913086: Connected

It hangs at line 221 forever I believe.

So I feel like somehow the API lock deadlocks. I had this quite a few times. It's not very robust in that regard :(

Can anyone help me out here please?

Thanks

Noah

[Vidar Berg]

Hi Noah,

3 seconds sounds quite slow. I have a similar pc-ble-driver script which I have used as a client for ble_app_uart peripheral example, but it doesn't feel like there is much of a noticeably delay for service discovery. Can you try to connect with a faster connection interval and see how much that helps (7.5 ms is fastest)?

 

Fullscreen 1856.nus_central.py Download

#
# Copyright (c) 2016 Nordic Semiconductor ASA
# All rights reserved.
#
# Redistribution and use in source and binary forms, with or without modification,
# are permitted provided that the following conditions are met:
#
#   1. Redistributions of source code must retain the above copyright notice, this
#   list of conditions and the following disclaimer.
#
#   2. Redistributions in binary form must reproduce the above copyright notice, this
#   list of conditions and the following disclaimer in the documentation and/or
#   other materials provided with the distribution.
#
#   3. Neither the name of Nordic Semiconductor ASA nor the names of other
#   contributors to this software may be used to endorse or promote products
#   derived from this software without specific prior written permission.
#
#   4. This software must only be used in or with a processor manufactured by Nordic
#   Semiconductor ASA, or in or with a processor manufactured by a third party that
#   is used in combination with a processor manufactured by Nordic Semiconductor.
#
#   5. Any software provided in binary or object form under this license must not be
#   reverse engineered, decompiled, modified and/or disassembled.
#
# THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS "AS IS" AND
# ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE IMPLIED
# WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE ARE
# DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT HOLDER OR CONTRIBUTORS BE LIABLE FOR
# ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES
# (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES;
# LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON
# ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT
# (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE OF THIS
# SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
#

import sys
import time
import logging
from queue import Queue, Empty
from pc_ble_driver_py.observers import *

TARGET_DEV_NAME = "Nordic_UART"
CONNECTIONS = 1
CFG_TAG = 1


def init(conn_ic_id):
    # noinspection PyGlobalUndefined
    global config, BLEDriver, BLEAdvData, BLEEvtID, BLEAdapter, BLEEnableParams, BLEGapTimeoutSrc, BLEUUID, BLEUUIDBase, BLEConfigCommon, BLEConfig, BLEConfigConnGatt, BLEGapScanParams, BLEGapConnParams
    from pc_ble_driver_py import config

    config.__conn_ic_id__ = conn_ic_id
    # noinspection PyUnresolvedReferences
    from pc_ble_driver_py.ble_driver import (
        BLEDriver,
        BLEAdvData,
        BLEEvtID,
        BLEEnableParams,
        BLEGapTimeoutSrc,
        BLEUUID,
        BLEUUIDBase,
        BLEGapScanParams,
        BLEGapConnParams,
        BLEConfigCommon,
        BLEConfig,
        BLEConfigConnGatt,
    )

    # noinspection PyUnresolvedReferences
    from pc_ble_driver_py.ble_adapter import BLEAdapter

    global nrf_sd_ble_api_ver
    nrf_sd_ble_api_ver = config.sd_api_ver_get()


class NusCollector(BLEDriverObserver, BLEAdapterObserver):
    def __init__(self, adapter):
        super(NusCollector, self).__init__()
        self.first = 1
        self.adapter = adapter
        self.conn_q = Queue()
        self.adapter.observer_register(self)
        self.adapter.driver.observer_register(self)
        self.adapter.default_mtu = 300
        self.nus_base = BLEUUIDBase([
            0x6e, 0x40, 0x00, 0x00, 0xb5, 0xa3, 0xf3, 0x93, 0xe0, 0xa9, 0xe5, 0x0e, 0x24, 0xdc, 0xca, 0x9e
        ])
        self.nus_rx = BLEUUID(0x0002, self.nus_base)
        self.nus_tx = BLEUUID(0x0003, self.nus_base)

    def open(self):
        self.adapter.driver.open()
        if config.__conn_ic_id__ == "NRF51":
            self.adapter.driver.ble_enable(
                BLEEnableParams(
                    vs_uuid_count=1,
                    service_changed=0,
                    periph_conn_count=0,
                    central_conn_count=1,
                    central_sec_count=0,
                )
            )
        elif config.__conn_ic_id__ == "NRF52":
            gatt_cfg = BLEConfigConnGatt()
            gatt_cfg.att_mtu = self.adapter.default_mtu
            gatt_cfg.tag = CFG_TAG
            self.adapter.driver.ble_cfg_set(BLEConfig.conn_gatt, gatt_cfg)

            self.adapter.driver.ble_enable()
            self.adapter.driver.ble_vs_uuid_add(self.nus_base)



    def close(self):
        self.adapter.driver.close()

    def connect_and_discover(self):
        scan_duration = 5
        scan_params = BLEGapScanParams(interval_ms=200, window_ms=150, timeout_s=scan_duration)
        message = "We are connected!\r\n"

        self.adapter.driver.ble_gap_scan_start(scan_params=scan_params)

        try:
            new_conn = self.conn_q.get(timeout=scan_duration)
            self.adapter.service_discovery(new_conn)
            self.adapter.enable_notification(new_conn, self.nus_tx)
            data = [ord(n) for n in list(message)]
            self.adapter.write_cmd(new_conn, self.nus_rx, data)
            return new_conn
        except Empty:
            print("No device advertising with name {TARGET_DEV_NAME} found.")
            return None

    def on_gattc_evt_exchange_mtu_rsp(self, ble_driver, conn_handle, status, att_mtu):
        print("ATT MTU updated to {}".format(att_mtu))
    
    def on_gap_evt_data_length_update(
        self, ble_driver, conn_handle, data_length_params
    ):
        print("Max rx octets: {}".format(data_length_params.max_rx_octets))
        print("Max tx octets: {}".format(data_length_params.max_tx_octets))
        print("Max rx time: {}".format(data_length_params.max_rx_time_us))
        print("Max tx time: {}".format(data_length_params.max_tx_time_us))

    def on_gatts_evt_exchange_mtu_request(self, ble_driver, conn_handle, client_mtu):
        print("Client requesting to update ATT MTU to {} bytes".format(client_mtu))
    def on_gap_evt_connected(
        self, ble_driver, conn_handle, peer_addr, role, conn_params
    ):
        print("New connection: {}".format(conn_handle))
        self.conn_q.put(conn_handle)

    def on_gap_evt_disconnected(self, ble_driver, conn_handle, reason):
        print("Disconnected: {} {}".format(conn_handle, reason))

    def on_gap_evt_adv_report(
        self, ble_driver, conn_handle, peer_addr, rssi, adv_type, adv_data
    ):
        conn_params = BLEGapConnParams(min_conn_interval_ms=7.5, max_conn_interval_ms=7.5, conn_sup_timeout_ms=4000, slave_latency=0)
        
        if BLEAdvData.Types.complete_local_name in adv_data.records:
            dev_name_list = adv_data.records[BLEAdvData.Types.complete_local_name]

        elif BLEAdvData.Types.short_local_name in adv_data.records:
            dev_name_list = adv_data.records[BLEAdvData.Types.short_local_name]

        else:
            return

        dev_name = "".join(chr(e) for e in dev_name_list)
        address_string = "".join("{0:02X}".format(b) for b in peer_addr.addr)
        print(
            "Received advertisment report, address: 0x{}, device_name: {}".format(
                address_string, dev_name
            )
        )

        if dev_name == TARGET_DEV_NAME:
            self.adapter.connect(peer_addr, conn_params = conn_params, tag=CFG_TAG)

    def on_notification(self, ble_adapter, conn_handle, uuid, data):
        if len(data) > 32:
            data = "({}...)".format(data[0:10])
        print("Connection: {}, {} = {}".format(conn_handle, uuid, data))


def main(selected_serial_port):
    print("Serial port used: {}".format(selected_serial_port))
    driver = BLEDriver(
        serial_port=selected_serial_port, auto_flash=False, baud_rate=1000000, log_severity_level="info"
    )

    adapter = BLEAdapter(driver)
    collector = NusCollector(adapter)
    collector.open()
    conn = collector.connect_and_discover()

    while conn is not None:
        time.sleep(100)

    collector.close()


def item_choose(item_list):
    for i, it in enumerate(item_list):
        print("\t{} : {}".format(i, it))
    print(" ")

    while True:
        try:
            choice = int(input("Enter your choice: "))
            if (choice >= 0) and (choice < len(item_list)):
                break
        except Exception:
            pass
        print("\tTry again...")
    return choice


if __name__ == "__main__":
    #logging.basicConfig(
    #    level="DEBUG",
    #   format="%(asctime)s [%(thread)d/%(threadName)s] %(message)s",
    #)
    serial_port = None
    if len(sys.argv) < 2:
        print("Please specify connectivity IC identifier (NRF51, NRF52)")
        exit(1)
    init(sys.argv[1])
    if len(sys.argv) == 3:
        serial_port = sys.argv[2]
    else:
        descs = BLEDriver.enum_serial_ports()
        choices = ["{}: {}".format(d.port, d.serial_number) for d in descs]
        choice = item_choose(choices)
        serial_port = descs[choice].port
    main(serial_port)
    quit()

Best regards,

Vidar

[Yatekii]

Thank you very much Vidar Berg!

This made connecting faster. I set this before, but maybe I accidentally didn't use it anymore in refactoring.

The problem is that in 80% of the cases the program just hangs after:

6.4373016357421875e-06: Start
Received advertisment report, address: C0:58:FA:AA:28:8C, device_name: zigfred
0.018852949142456055: Found zigfred
0.0011315345764160156: Stopped scan
Heading to discovery

or

6.4373016357421875e-06: Start
Received advertisment report, address: C0:58:FA:AA:28:8C, device_name: zigfred
0.018852949142456055: Found zigfred
0.0011315345764160156: Stopped scan
Heading to discovery
New connection: 0
{'status': <BLEGattStatusCode.success: 0>, 'services': [<pc_ble_driver_py.ble_driver.BLEService object at 0x7f48f8719c70>]}
{'status': <BLEGattStatusCode.attribute_not_found: 266>, 'services': []}
0.30429744720458984: Connected

Which is very bad.

I am not sure if I might be hitting: https://github.com/NordicSemiconductor/pc-ble-driver-py/issues/55

I'd appreciate help here very much, because if the entire stack is flaky like this, there is no way I can use this for production :/

EDIT: I tried to run your script, which dies with 0x3001 (BLE_NOT_ENABLED) on me. It works fine with my script tho. So this really hints at race conditions :(

EDIT2: When my script (the one I posted) hangs, I see this on the logger:

2021-02-04 11:58:51,867 [140261401286400/EventThread] evt> timeout conn(65535)
 src(BLEGapTimeoutSrc.conn)

I don't know why it timeouts. And it must be the PC software because the device connects fine with everything else!

EDIT3: I fixed the hang apparently (it was a dumb mistake). Sadly Service discovery now still takes 1.1seconds. Not nice!
Also, the entire python lib swallows exceptions. So when the program hanged it actually threw an exception but I couldn't see it. This is horrible!
Also, before I had to add a VS UUID to make my custom cahracteristic work. Now it seems to work without (even after rebooting the dongle!). Very dodgy ...

I hope you can give me some insight here.

Best,

Noah

[Vidar Berg]

Hi Noah,

Could you try to quickly mody my script with your UUIDs (replace nus_base, nus_rx and nus_tx) and see if my script is any faster when it comes to service discovery?

Yatekii said:

I tried to run your script, which dies with 0x3001 (BLE_NOT_ENABLED) on me.

 Are you able to tell where this error was returned from? The error usually means that a Softdevice API is called before the Softdevice has been fully enabled.

Best regards,

Vidar

[Yatekii]

Vidar Berg

Sadly your script always crashes with:

Serial port used: /dev/ttyACM0
Traceback (most recent call last):
  File "nus.py", line 266, in <module>
    main(serial_port)
  File "nus.py", line 225, in main
    conn = collector.connect_and_discover()
  File "nus.py", line 141, in connect_and_discover
    self.adapter.driver.ble_gap_scan_start(scan_params=scan_params)
  File "/home/yatekii/repos/technokrat/zigfred/zigfred_test/venv/lib/python3.8/site-packages/pc_ble_driver_py/ble_driver.py", line 103, in wrapper
    raise NordicSemiException(
pc_ble_driver_py.exceptions.NordicSemiException: Failed to ble_gap_scan_start. Error code: 12289

I believe this is due to race conditions in the lib as I had this sometimes too but it seems gone now.

[Vidar Berg]

I'm a bit suprised that you are getting this error. The issue report describes a race condition in the SD event synchronization mechanism, and is, as far as I can tell, not related to the BLE_NOT_ENABLED error you are getting. Also, I don't recall seeing the error when I've used the script here.

I assume you are using the latest pc-ble-driver-py package, but have you also made sure to program the latest connectivity hex onto the dongle?

Connectivity FW

https://github.com/NordicSemiconductor/pc-ble-driver/tree/release/4.1.2/hex/sd_api_v5