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?

  • 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.

  • 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
    

Related