Beware that this post is related to an SDK in maintenance mode
More Info: Consider nRF Connect SDK for new designs
This post is older than 2 years and might not be relevant anymore
More Info: Consider searching for newer posts

[FDS] PeerManager error -> try to find record which recently has been invalidated

Hi,

I am using SDK13 and  have noticed some critical issue with peer manager while bonding. The problem is that after performing dfu of my device (which was bonded with two phones before update) when I try to connect to device with first bonded device everything goes ok, but when I try to connect with the second phone device reset due to catching error inside pm_evt_handler

pm_evt_handler(...)
{
 ...
 
    case PM_EVT_PEER_DATA_UPDATE_FAILED:
    {
        APP_ERROR_CHECK(p_evt->params.peer_data_update_failed.error);
    }
...
}

This error is caused by fds which try to find record with function:

 

peer_data_find(...)
{
...
    ret = fds_record_find(file_id, record_key, p_desc, &ftok);

    if (ret != FDS_SUCCESS)
    {
        return NRF_ERROR_NOT_FOUND; <--- CALLED ERROR
    }
    
...
}

After my analysis error is caused by trying to find record which was recently invalidated (fds record keys overwritten with 0x0000). This error reproduce each time following steps below:

  1. Program device with FW (bootloader + application) over JLink
  2. In application perform bonding procedure for 2 phones (1st one HUAWEI HONOR 5X, 2nd Xiaomi Redmi Note 4)
  3. Enter bootloader and perform application dfu (same application as in 1st step)
  4. After DFU in application perform connection of 1st phone -> works perfectly
  5. Perform connection with 2nd phone -> cause error in code shown abowe.

After spending some time with that problem I suggest that it is caused by some race condition in updating peer manager bonding records.

What shall I do to prevent situation because it cause brick of all of my production devices?

Parents
  • Hello,

    I tried to perform the test that you described, but I couldn't reproduce it. It was one phone and one DK using nRF Connect for Desktop. Can you try to reproduce it using the example:

    SDK\examples\ble_peripheral\experimental_ble_app_buttonless_dfu. 

    Does it happen if you use a "clean" SDK (That is just unzipped, and not modified in any way). Maybe you changed something in another project that affected some common files?

    Best regards,

    Edvin

  • I can try, but what "application" have you use? You mention about bootloader but additionaly you need some application perform bonding (Bootloader + SD + App) and perform bonding in Application and then go back to new (fresh) application and try to connect.

  • You are right but it is not the flow I mention. Once again, you need:

    1. bootloader programmed into device
    2. using flashed bootloader perform DFU process and send to device Application (eg. ble_app_multirole_lesc)
    3. Bond in ble_app_multirole_lesc (with 2 separate devices)
    4. enter bootloader and once again perform dfu with the same lesc application
    5. When device enter application (after dfu) mention recently bug should appear when you try to connect with phones
  • I did now, and it works here (again, one phone and one DK using nRF Connect).

    I flashed the bootloader on one DK, updated to the LESC application via DFU, bonded with 1: my phone, and 2: the DK that I used with nRF Connect to update the firmware. 

    Then updated the firmware again with DFU, to the same application with a higher application version. Then checked with both devices. They were still bonded. 

    The reason I asked you to test the experimental_ble_app_buttonless_dfu example is that it doesn't use LESC. I wanted to check if the issue was related to the actual bonding procedure or FDS. Not all phones support LESC. None of the phones that you listed are particularly new. Are you sure they both support LESC?

    Can you please try either with a new unzip of the SDK that is not modified, and if it still doesn't work, can you test with the ble_app_buttonless example? Remember to change the line that I mentioned in the previous reply to trigger bonding.

    In case you find it helpful, here is the script that I used to generate the images and flash the bootloader and the first DFU to get the LESC or buttonless application up and running with a bootloader. You need to adapt it to use your serial number (instead of 123456789) and the correct private.key and COM port for nrfutil.

    :: compile the bootloader
    make -j9
    
    :: flash softdevice and bootloader 
    nrfjprog -e --snr 123456789
    nrfjprog --program ..\..\..\..\..\components\softdevice\s132\hex\s132_nrf52_4.0.2_softdevice.hex --verify --snr 123456789
    nrfjprog --program _build\nrf52832_xxaa_s132.hex --verify --snr 123456789
    nrfjprog --reset --snr 123456789
    
    :: compile the buttonless example
    make -j9 -C ..\..\..\..\ble_peripheral\experimental_ble_app_buttonless_dfu\pca10040\s132\armgcc
    del files\buttonless_bonding.hex
    copy ..\..\..\..\ble_peripheral\experimental_ble_app_buttonless_dfu\pca10040\s132\armgcc\_build\nrf52832_xxaa.hex files
    ren files\nrf52832_xxaa.hex buttonless_bonding.hex
    
    :: compile the LESC example
    make -j9 -C ..\..\..\..\ble_central_and_peripheral\experimental\ble_app_multirole_lesc\pca10040\s132\armgcc
    del files\lesc.hex
    copy ..\..\..\..\ble_central_and_peripheral\experimental\ble_app_multirole_lesc\pca10040\s132\armgcc\_build\nrf52832_xxaa.hex files
    ren files\nrf52832_xxaa.hex lesc.hex
    
    :: generate buttonless images with 3 different application-versions
    nrfutil pkg generate --application files\buttonless_bonding.hex --application-version 1 --hw-version 52 --sd-req 0x98 --key-file files\private.key files\buttonless_1.zip
    nrfutil pkg generate --application files\buttonless_bonding.hex --application-version 2 --hw-version 52 --sd-req 0x98 --key-file files\private.key files\buttonless_2.zip
    nrfutil pkg generate --application files\buttonless_bonding.hex --application-version 3 --hw-version 52 --sd-req 0x98 --key-file files\private.key files\buttonless_3.zip
    
    :: generate lesc images with 3 different application-versions
    nrfutil pkg generate --application files\lesc.hex --application-version 1 --hw-version 52 --sd-req 0x98 --key-file files\private.key files\lesc_1.zip
    nrfutil pkg generate --application files\lesc.hex --application-version 2 --hw-version 52 --sd-req 0x98 --key-file files\private.key files\lesc_2.zip
    nrfutil pkg generate --application files\lesc.hex --application-version 3 --hw-version 52 --sd-req 0x98 --key-file files\private.key files\lesc_3.zip
    
    :: Perform the DFU to first application.
    ::nrfutil dfu ble -pkg files\buttonless_1.zip -ic NRF52 -p COM9 -n "Dfu_Targ" -f
    nrfutil dfu ble -pkg files\lesc_1.zip -ic NRF52 -p COM9 -n "Dfu_Targ" -f
    
    

    EDIT: This .bat script is placed in the armgcc folder of the bootloader project. The private.key is located in a folder called "files" inside this folder.

    Best regards,

    Edvin

  • I have tried to reproduce my problem with bare sdk13 but I cannot perform OTAU. I have called everything like you share in *.bat file. Unfortunately each time (on PC nrfconnect app) I am receiving:

    Scan started
    10:32:22.022
    Disconnected from device E9:AD:02:C5:09:48, reason: BLE_HCI_CONNECTION_TIMEOUT
    10:32:22.487
    Scan stopped
    10:32:23.327
    Connecting to device
    10:32:23.388
    Connected to device E9:AD:02:C5:09:48
    10:32:23.645
    Attribute value read, handle: 0x03, value (0x): 44-66-75-54-61-72-67
    10:32:29.793
    Disconnected from device E9:AD:02:C5:09:48, reason: undefined
    10:32:29.796
    Performing DFU with file: lesc_test_1.zip
    10:32:36.216
    Aborting DFU.
    After flashing bl + sd to DK (pca10040) both LED1 and LED3 lit but after connection nothing has changed. Compared to *.hex file provided precompiled (examples/dfu/bootloader_secure_ble/hex) after connection LED1 turns off and LED2 start lit.What am I doing wrong?
  • What does it say in the log where you try to perform the DFU from?

    Without knowing more, I can't help much other than pointing to the guide on how to perform DFU.

    The precompiled hex file in examples\dfu\bootloader_secure_ble\hex probably contains the softdevice as well. Also, remember that you need to use a DFU image signed with the same key as you use in your bootloader, so they probably doesn't match. Read through the guide on how to generate your own set of keys.

  • I have perform all steps mention in "how to perform DFU" and thats why I am asking that question.
    Yes I have generated my custom key, add it to project and sing application.zip with my private key as mention in "how to...".

    The only logs I receive comes from nrfconnect application which I show you in previous message.

    Can you please provide me full flow you are doing to prepare bootloader and lesc app (including full path from sdk13 and how you are generating keys and where you are putting them)? Maby I miss something which it is crutial to have same start as You to try figure out issue I have mention in beginning post.

Reply
  • I have perform all steps mention in "how to perform DFU" and thats why I am asking that question.
    Yes I have generated my custom key, add it to project and sing application.zip with my private key as mention in "how to...".

    The only logs I receive comes from nrfconnect application which I show you in previous message.

    Can you please provide me full flow you are doing to prepare bootloader and lesc app (including full path from sdk13 and how you are generating keys and where you are putting them)? Maby I miss something which it is crutial to have same start as You to try figure out issue I have mention in beginning post.

Children
  • Ok. Can you try to use nrfutil with the following commands? dfu_image.zip should be the path to your DFU image, and COMX should be the com port that the connectivity DK (not the DK containing the bootloader) is using, and __name__ should be the advertising name of your device. In an unmodified Bootloader project, that would be "DfuTarg".

    PS: run "nrfjprog -e" on the DK that is working as your connectivity DK (the same DK that you used with nRF Connect for Desktop).

    nrfutil -v -v -o dfu_log_file.log dfu ble -pkg dfu_image.zip -ic NRF52 -p COMX -n "__name__" -f

    Then attach the log file: dfu_log_file.log, that is generated in the same folder as you run your cmd window from.

  • In attachment you will see two logs file (dfu_log_file.log and logs.txt - more precise with error capture), and I attache bootloader hex file and zipped and signed lesc application to perform otau.

    bl.hex

    lesc_bug_test_1.zip

    dfu_log_file.log

    2019-09-04 15:48:41,821 Shared library: /home/patlas/.local/lib/python2.7/site-packages/pc_ble_driver_py/lib/linux/x86_64/libpc_ble_driver_shared_sd_api_v3.so
    2019-09-04 15:48:41,821 Swig module name: pc_ble_driver_sd_api_v3
    Board already flashed with connectivity firmware.
    2019-09-04 15:48:44,499 Using connectivity board at serial port: /dev/ttyACM0
    2019-09-04 15:48:44,514 Sending Application image.
    2019-09-04 15:48:48,078 
    BLE: ble_enable with local ATT MTU: 247
    2019-09-04 15:48:48,092 BLE: Scanning for DfuTarg
    2019-09-04 15:48:48,113 evt> adv_report conn(65535)
     peer_addr(70:B3:D5:C5:3F:19)
     rssi(-91)
     adv_type(BLEGapAdvType.connectable_undirected)
    2019-09-04 15:48:48,113 Received advertisement report, address: 0x70B3D5C53F19, device_name: 
    2019-09-04 15:48:48,117 evt> adv_report conn(65535)
     peer_addr(70:B3:D5:C5:3F:19)
     rssi(-89)
     adv_type(None)
    2019-09-04 15:48:48,118 Received advertisement report, address: 0x70B3D5C53F19, device_name: Plug
    2019-09-04 15:48:48,125 evt> adv_report conn(65535)
     peer_addr(1C:38:77:D0:0A:A0)
     rssi(-68)
     adv_type(BLEGapAdvType.non_connectable_undirected)
    2019-09-04 15:48:48,126 Received advertisement report, address: 0x1C3877D00AA0, device_name: 
    2019-09-04 15:48:48,131 evt> adv_report conn(65535)
     peer_addr(E9:AD:02:C5:09:48)
     rssi(-51)
     adv_type(BLEGapAdvType.connectable_undirected)
    2019-09-04 15:48:48,132 Received advertisement report, address: 0xE9AD02C50948, device_name: DfuTarg
    2019-09-04 15:48:48,132 BLE: Found target advertiser, address: 0xE9AD02C50948, name: DfuTarg
    2019-09-04 15:48:48,132 BLE: Connecting to 0xE9AD02C50948
    2019-09-04 15:48:48,139 evt> adv_report conn(65535)
     peer_addr(E9:AD:02:C5:09:48)
     rssi(-51)
     adv_type(None)
    2019-09-04 15:48:48,140 Received advertisement report, address: 0xE9AD02C50948, device_name: 
    2019-09-04 15:48:48,140 BLE: Found target advertiser, address: 0xE9AD02C50948, name: 
    2019-09-04 15:48:48,140 BLE: Connecting to 0xE9AD02C50948
    2019-09-04 15:48:48,146 evt> adv_report conn(65535)
     peer_addr(70:B3:D5:C5:38:0A)
     rssi(-81)
     adv_type(BLEGapAdvType.connectable_undirected)
    2019-09-04 15:48:48,146 Received advertisement report, address: 0x70B3D5C5380A, device_name: 
    2019-09-04 15:48:48,152 evt> adv_report conn(65535)
     peer_addr(70:B3:D5:C5:3B:ED)
     rssi(-82)
     adv_type(BLEGapAdvType.connectable_undirected)
    2019-09-04 15:48:48,153 Received advertisement report, address: 0x70B3D5C53BED, device_name: 
    2019-09-04 15:48:48,159 evt> adv_report conn(65535)
     peer_addr(70:B3:D5:C5:3B:ED)
     rssi(-82)
     adv_type(None)
    2019-09-04 15:48:48,160 Received advertisement report, address: 0x70B3D5C53BED, device_name: Plug
    2019-09-04 15:48:48,164 BLE: Connected to [233L, 173L, 2L, 197L, 9L, 72L]
    2019-09-04 15:48:49,213 Successfully Connected
    2019-09-04 15:48:49,214 BLE: Service Discovery
    2019-09-04 15:48:49,267 evt> on_gattc_evt_prim_srvc_disc_rsp status(BLEGattStatusCode.success) conn(0)
     Service uuid(0x1800) start handle(1) end handle(9)
     Service uuid(0x1801) start handle(10) end handle(13)
     Service uuid(0xFE59) start handle(14) end handle(65535)
    2019-09-04 15:48:49,327 evt> on_gattc_evt_char_disc_rsp status(BLEGattStatusCode.success) conn(0)
     Characteristic uuid(0x2A00) properties(CharProperties(broadcast=0L, read=1L, write_wo_resp=0L, write=1L, notify=0L, indicate=0L, auth_signed_wr=0L)) declaration handle(2) value handle(3)
     Characteristic uuid(0x2A01) properties(CharProperties(broadcast=0L, read=1L, write_wo_resp=0L, write=0L, notify=0L, indicate=0L, auth_signed_wr=0L)) declaration handle(4) value handle(5)
     Characteristic uuid(0x2A04) properties(CharProperties(broadcast=0L, read=1L, write_wo_resp=0L, write=0L, notify=0L, indicate=0L, auth_signed_wr=0L)) declaration handle(6) value handle(7)
    2019-09-04 15:48:49,414 evt> on_gattc_evt_char_disc_rsp status(BLEGattStatusCode.success) conn(0)
     Characteristic uuid(0x2AA6) properties(CharProperties(broadcast=0L, read=1L, write_wo_resp=0L, write=0L, notify=0L, indicate=0L, auth_signed_wr=0L)) declaration handle(8) value handle(9)
    2019-09-04 15:48:49,473 evt> on_gattc_evt_char_disc_rsp status(BLEGattStatusCode.attribute_not_found) conn(0)
     
    2019-09-04 15:48:49,534 evt> on_gattc_evt_desc_disc_rsp status(BLEGattStatusCode.success) conn(0)
     Descriptor uuid(0x2A00) handle(3)
    2019-09-04 15:48:49,624 evt> on_gattc_evt_desc_disc_rsp status(BLEGattStatusCode.success) conn(0)
     Descriptor uuid(0x2A01) handle(5)
    2019-09-04 15:48:49,684 evt> on_gattc_evt_desc_disc_rsp status(BLEGattStatusCode.success) conn(0)
     Descriptor uuid(0x2A04) handle(7)
    2019-09-04 15:48:49,744 evt> on_gattc_evt_desc_disc_rsp status(BLEGattStatusCode.success) conn(0)
     Descriptor uuid(0x2AA6) handle(9)
    2019-09-04 15:48:49,834 evt> on_gattc_evt_char_disc_rsp status(BLEGattStatusCode.success) conn(0)
     Characteristic uuid(0x2A05) properties(CharProperties(broadcast=0L, read=0L, write_wo_resp=0L, write=0L, notify=0L, indicate=1L, auth_signed_wr=0L)) declaration handle(11) value handle(12)
    2019-09-04 15:48:49,893 evt> on_gattc_evt_char_disc_rsp status(BLEGattStatusCode.attribute_not_found) conn(0)
     
    2019-09-04 15:48:49,955 evt> on_gattc_evt_desc_disc_rsp status(BLEGattStatusCode.success) conn(0)
     Descriptor uuid(0x2A05) handle(12)
     Descriptor uuid(0x2902 (Standard.cccd)) handle(13)
    2019-09-04 15:48:50,045 evt> on_gattc_evt_char_disc_rsp status(BLEGattStatusCode.success) conn(0)
     Characteristic uuid(0x02) properties(CharProperties(broadcast=0L, read=0L, write_wo_resp=1L, write=0L, notify=0L, indicate=0L, auth_signed_wr=0L)) declaration handle(15) value handle(16)
    2019-09-04 15:48:50,105 evt> on_gattc_evt_char_disc_rsp status(BLEGattStatusCode.success) conn(0)
     Characteristic uuid(0x01) properties(CharProperties(broadcast=0L, read=0L, write_wo_resp=0L, write=1L, notify=1L, indicate=0L, auth_signed_wr=0L)) declaration handle(17) value handle(18)
    2019-09-04 15:48:50,163 evt> on_gattc_evt_char_disc_rsp status(BLEGattStatusCode.attribute_not_found) conn(0)
     
    2019-09-04 15:48:50,254 evt> on_gattc_evt_desc_disc_rsp status(BLEGattStatusCode.success) conn(0)
     Descriptor uuid(0x02) handle(16)
    2019-09-04 15:48:50,314 evt> on_gattc_evt_desc_disc_rsp status(BLEGattStatusCode.success) conn(0)
     Descriptor uuid(0x01) handle(18)
    2019-09-04 15:48:50,374 evt> on_gattc_evt_desc_disc_rsp status(BLEGattStatusCode.success) conn(0)
     Descriptor uuid(0x2902 (Standard.cccd)) handle(19)
    2019-09-04 15:48:50,463 evt> on_gattc_evt_desc_disc_rsp status(BLEGattStatusCode.attribute_not_found) conn(0)
     
    2019-09-04 15:48:50,470 BLE: Enabling longer ATT MTUs
    2019-09-04 15:48:50,471 Sending GATTC MTU exchange request: 247
    2019-09-04 15:48:50,523 GATTC: ATT MTU: 23
    2019-09-04 15:48:50,523 ATT MTU exchanged: conn_handle=0 att_mtu=23
    2019-09-04 15:48:50,541 BLE: Enabling Notifications
    2019-09-04 15:48:50,584 evt> on_gattc_evt_write_rsp conn(0)
     status(BLEGattStatusCode.success)
     error_handle(0)
     attr_handle(19)
     write_op(BLEGattWriteOperation.write_req)
     offset(0)
     data([])
    2019-09-04 15:48:50,612 BLE: Set Packet Receipt Notification 0
    2019-09-04 15:48:50,674 evt> on_gattc_evt_write_rsp conn(0)
     status(BLEGattStatusCode.success)
     error_handle(0)
     attr_handle(18)
     write_op(BLEGattWriteOperation.write_req)
     offset(0)
     data([])
    2019-09-04 15:48:50,678 evt> on_gattc_evt_hvx status(BLEGattStatusCode.success) conn(0)
     error_handle(0)
     attr_handle(18)
     hvx_type(BLEGattHVXType.notification)
     data([96L, 2L, 1L])
    2019-09-04 15:48:50,683 Sending init packet...
    2019-09-04 15:48:50,684 BLE: Selecting Object: type:1
    2019-09-04 15:48:50,734 evt> on_gattc_evt_write_rsp conn(0)
     status(BLEGattStatusCode.success)
     error_handle(0)
     attr_handle(18)
     write_op(BLEGattWriteOperation.write_req)
     offset(0)
     data([])
    2019-09-04 15:48:50,739 evt> on_gattc_evt_hvx status(BLEGattStatusCode.success) conn(0)
     error_handle(0)
     attr_handle(18)
     hvx_type(BLEGattHVXType.notification)
     data([96L, 6L, 1L, 0L, 1L, 0L, 0L, 0L, 0L, 0L, 0L, 0L, 0L, 0L, 0L])
    2019-09-04 15:48:50,755 BLE: Object selected: max_size:256 offset:0 crc:0
    2019-09-04 15:48:50,824 evt> on_gattc_evt_write_rsp conn(0)
     status(BLEGattStatusCode.success)
     error_handle(0)
     attr_handle(18)
     write_op(BLEGattWriteOperation.write_req)
     offset(0)
     data([])
    Traceback (most recent call last):
      File "/home/patlas/.local/bin/nrfutil", line 11, in <module>
        sys.exit(cli())
      File "/home/patlas/.local/lib/python2.7/site-packages/click/core.py", line 764, in __call__
        return self.main(*args, **kwargs)
      File "/home/patlas/.local/lib/python2.7/site-packages/click/core.py", line 717, in main
        rv = self.invoke(ctx)
      File "/home/patlas/.local/lib/python2.7/site-packages/click/core.py", line 1137, in invoke
        return _process_result(sub_ctx.command.invoke(sub_ctx))
      File "/home/patlas/.local/lib/python2.7/site-packages/click/core.py", line 1137, in invoke
        return _process_result(sub_ctx.command.invoke(sub_ctx))
      File "/home/patlas/.local/lib/python2.7/site-packages/click/core.py", line 956, in invoke
        return ctx.invoke(self.callback, **ctx.params)
      File "/home/patlas/.local/lib/python2.7/site-packages/click/core.py", line 555, in invoke
        return callback(*args, **kwargs)
      File "/home/patlas/.local/lib/python2.7/site-packages/nordicsemi/__main__.py", line 814, in ble
        dfu.dfu_send_images()
      File "/home/patlas/.local/lib/python2.7/site-packages/nordicsemi/dfu/dfu.py", line 122, in dfu_send_images
        self._dfu_send_image(self.manifest.application)
      File "/home/patlas/.local/lib/python2.7/site-packages/nordicsemi/dfu/dfu.py", line 90, in _dfu_send_image
        self.dfu_transport.send_init_packet(data)
      File "/home/patlas/.local/lib/python2.7/site-packages/nordicsemi/dfu/dfu_transport_ble.py", line 500, in send_init_packet
        self.__create_command(len(init_packet))
      File "/home/patlas/.local/lib/python2.7/site-packages/nordicsemi/dfu/dfu_transport_ble.py", line 564, in __create_command
        self.__create_object(0x01, size)
      File "/home/patlas/.local/lib/python2.7/site-packages/nordicsemi/dfu/dfu_transport_ble.py", line 572, in __create_object
        self.__get_response(DfuTransportBle.OP_CODE['CreateObject'])
      File "/home/patlas/.local/lib/python2.7/site-packages/nordicsemi/dfu/dfu_transport_ble.py", line 641, in __get_response
        operation)))
    pc_ble_driver_py.exceptions.NordicSemiException: Timeout: operation - CreateObject
    

  • What SDK version do you use? What chip do you use? nRF52832? nRF52840? What Softdevice do you use?

  • SDK: nRF5_SDK_13.0.0_04a0bfd.zip
    SoftDevice: from SDK
    chip: nRF52832 (DK10040)
    nrfutil: 5.2.0 (try 3.2 and 3.4)

  • Ok. I agree, it doesn't work, but I don't know why. Looks like your bootloader crashes somewhere.

    This set works (not that it helps much)

    BL.hexlesc_1.zips132_nrf52_4.0.2_softdevice.hexlesc_2.zip

    Nothing fancy done to the bootloader (except changing the advertising name from "DfuTarg" to "Dfu_Targ" to separate it from other DFU devices in the office).

    Have you done any changes to the bootloader project?

Related