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.

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

  • I have finally solve problem - I've been using newer gcc compiler (version 5.4.3). When I switch to 4.9.3 sdk example builds starts working like a charm. Assuming it as a reason of my examples problem this mean that somewere in SDK/SD code there is missing ALIGNMENT or another issue - try to reproduce it.

    Since now I am switching to my base topic question with FDS hazardous.

Reply
  • I have finally solve problem - I've been using newer gcc compiler (version 5.4.3). When I switch to 4.9.3 sdk example builds starts working like a charm. Assuming it as a reason of my examples problem this mean that somewere in SDK/SD code there is missing ALIGNMENT or another issue - try to reproduce it.

    Since now I am switching to my base topic question with FDS hazardous.

Children
  • That is good news. You should use the compilers that are listed in the SDK release notes.

    GCC: GCC ARM Embedded 4.9 2015q3

    Can you test with an unmodified SDK and armgcc version 4.9 2015q3?

    As I mentioned in an earlier reply, I the LESC example, updated to the same application via DFU (a newer application version), and I am not able to reproduce this issue. Maybe you can give some instructions on how to reproduce your issue with an unmodified SDK?

    Best regards,

    Edvin

Related