Beware that this post is related to an SDK in maintenance mode
More Info: Consider nRF Connect SDK for new designs

Beacon output suddenly stops

Hello.

In the BLE software being developed, the device uses nRF52840, s140 v7.2.0 or v7.3.0, and I am building a system that periodically sends a beacon (ADV_NONCONN_IND) in the peripheral role at the same time as scanning in the central role.

In the software currently under development, after setting a beacon (ADV_NONCONN_IND) and executing ble_advertising_start, the advertisements at the set interval suddenly stops after a while.

The time it takes for the problem to occur varies, ranging from a few hours to several tens of hours, and other functions appear to be working fine even after the problem occurs.

The operation of this device is to continuously perform a sequence of transmitting beacons, connecting in a central role based on advertisements from external devices that capture the beacons, and then disconnecting after communication.
For this reason, the central role frequently start and stop scanning, connects and disconnects, but the peripheral role's beacon output has never stopped since the start advertising.

I believe that the output of ADV_NONCONN_IND started with ble_advertising_start will not stop unless sd_ble_gap_adv_stop is executed, but is it possible that external factors such as SCAN or connection of the central role can stop advertising of peripheral roles?

Also, as a failsafe, we are considering implementing code that monitors the advertisement output and restarts it when the advertisement stops, but is there a way to detect that the ADV_NONCONN_IND has been output to RADIO?
I looked into Radio Notification, but since the event callback can only receive the radio_active state, I determined that it is not possible to capture only the advertisement output in a multi-role operating environment.

Please give me some advice.

best regard.

  • Hello,  Edvin.

    > So your beacon is also scanning, and connecting to other devices from time to time, is that correct?

    I have drawn a simple sequence chart of the system.

    • The device emits a beacon (ADV_NONCONN_IND) at a 100 ms cycle and opens a 20 ms scan window at 20 ms intervals.
    • The iPhone catches the device's beacon and initiates ADV_IND.
    • The device uses the ADV_IND and SCAN_RSP information to make a connection request.
    • After connecting and completing the series of communications, it disconnects from the device, resumes scanning, and waits for the next ADV_IND.

    Beacons in the peripheral role are essentially configured when the device is first powered on and then continue to transmit signals continuously.

    In the central role, it receives ADV_IND and SCAN_RSP and makes decisions such as connection.
    Only one device can be connected at a time to the central, and a scanner that is stopped by CONNECT_IND will be restarted after disconnection.

    > The advertisements have stopped at the end of this graph, right?

    Yes, the radio notification stops after the graph ends and resets after 30 seconds.

    > It may happen that if there are too many events coming from the softdevice, that an event is not correctly forwarded to the application.

    This is important information.
    Does this mean that the SoftDevice is dropping events?

    If so, this could be the reason why BLE_GAP_EVT_CONNECTED is not raised and SCAN remains stopped even though SCAN is stopped after sd_ble_gap_connect.

    However, why does the peripheral role beacon also stop working at the same time?

    Since it's not something the app can fix, I think this may be a problem with the SoftDevice.

    Are there any parameters to increase the SoftDevice's event queue, or options to limit the types of events that are fired?

    > When this occurs, and you detect it, is it still possible to start advertising? What happens if you try to do so?

    Since we believe the issue is with the SoftDevice, we've set it to auto-reset if radio notifications stop for 30 seconds as a safety measure.

    In addition to this, if radio notifications stop for 1 second, we'll try to resume scanning and advertising if that's possible to recover.

    It will take some time to reproduce, but I will report the results once they are known.

    Best regards.

  • Hello.

    I was able to confirm No radio notification in the code that implemented the restart of SCAN and ADVERTISE.

    As a result, I found that restarting at the point where the problem occurred was ineffective.

    I have attached the log from just before the problem occurred below.

    00> ==SCAN_RSP== AdType:FF
    00> > Addr:60:4D:3C:3E:F0:A4 (Resolvable) RSSI:-41dBm(+0) raw:-41dBm
    00> 
    00> 
    00> @@@ scan_connect_judgement(687)->sd_ble_gap_connect
    00> +++ Connecting +++
    00> 
    00> @@@ on_connected_evt(160)->sd_ble_gattc_exchange_mtu_request
    00> @@@ data_length_update(89)->sd_ble_gap_data_length_update
    00> 03:29:33.6818  NRF_BLE_SCAN_EVT_CONNECTED(6)
    00> Connected to target : (7)
    00> 03:29:33.6830  BLE_GAP_EVT_CONNECTED(16)
    00> > conn_handle=0, conn_count=1
    00> 
    00> @@@ request_process(359)->sd_ble_gattc_primary_services_discover
    00> @@@ queue_process(215)->sd_ble_gattc_primary_services_discover
    00> ble_db_discovery_start: err_code=0
    00> 
    00> @@@ ble_evt_handler(1050)->sd_ble_gap_rssi_start
    00> [APP] CONNECTING
    00> 
    00> @@@ queue_process(215)->sd_ble_gattc_primary_services_discover
    00> 03:29:33.7282  BLE_GATTC_EVT_EXCHANGE_MTU_RSP(58)
    00> 03:29:33.7432  BLE_GAP_EVT_DATA_LENGTH_UPDATE(36)
    00> @@@ request_process(366)->sd_ble_gattc_characteristics_discover
    00> 03:29:33.7582  BLE_GATTC_EVT_PRIM_SRVC_DISC_RSP(48)
    00> @@@ request_process(366)->sd_ble_gattc_characteristics_discover
    00> @@@ request_process(372)->sd_ble_gattc_descriptors_discover
    00> @@@ request_process(372)->sd_ble_gattc_descriptors_discover
    00> 03:29:33.8931  BLE_DB_DISCOVERY_COMPLETE(0)
    00> 03:29:33.8933  BLE_NUS_C_EVT_DISCOVERY_COMPLETE(0)
    00> 03:29:33.8935  CMNBLE_vd_EventConnected(2381):  60:4D:3C:3E:F0:A4 (Resolvable)  elapsed(ms): 210
    00> 
    00> @@@ request_process(353)->sd_ble_gattc_write
    00> 03:29:33.8943  BLE_DB_DISCOVERY_AVAILABLE(3)
    00> 
    00> > LOCK conn_handle=-1->0
    00> 
    00> @@@ request_process(353)->sd_ble_gattc_write
    00> @@@ queue_process(208)->sd_ble_gattc_write
    00> 
    00> @@@ queue_process(208)->sd_ble_gattc_write
    00> 
    00> @@@ on_hvx(135)->sd_ble_gattc_hv_confirm
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> 
    00> @@@ request_process(353)->sd_ble_gattc_write
    00> 
    00> @@@ MdlBLE_en_Disconnect(1801)->sd_ble_gap_disconnect
    00> 
    00> 03:29:34.0880  BLE_GAP_EVT_DISCONNECTED(17)
    00> > conn_handle=0, conn_count=0, reason=0x16
    00> 
    00> @@@ ble_evt_handler(1062)->sd_ble_gap_rssi_stop
    00> > UNLOCK conn_handle=0
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> *** SCAN START ***
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> 
    00> 
    00> ==SCAN_RSP== AdType:FF
    00> > Addr:50:EE:9C:69:95:7A (Resolvable) RSSI:-47dBm(+0) raw:-47dBm
    00> 
    00> 
    00> ==SCAN_RSP== AdType:FF
    00> > Addr:50:EE:9C:69:95:7A (Resolvable) RSSI:-49dBm(+0) raw:-49dBm
    00> 
    00> 
    00> ==SCAN_RSP== AdType:FF
    00> > Addr:60:4D:3C:3E:F0:A4 (Resolvable) RSSI:-47dBm(+0) raw:-47dBm
    00> 
    00> 
    00> ==SCAN_RSP== AdType:FF
    00> > Addr:50:EE:9C:69:95:7A (Resolvable) RSSI:-50dBm(+0) raw:-50dBm
    00> 
    00> 
    00> ==SCAN_RSP== AdType:FF
    00> > Addr:60:4D:3C:3E:F0:A4 (Resolvable) RSSI:-47dBm(+0) raw:-47dBm
    00> 
    00> 
    00> ==SCAN_RSP== AdType:FF
    00> > Addr:60:4D:3C:3E:F0:A4 (Resolvable) RSSI:-41dBm(+0) raw:-41dBm
    00> 
    00> @@@ scan_connect_judgement(687)->sd_ble_gap_connect
    00> +++ Connecting +++
    00> 
    00> 
    00> *** No radio notification for a while(1000ms).
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> *** SCAN START ***
    00> 
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> @@@ MdlBLE_vd_AdvertisingStopReq(2570)->sd_ble_gap_adv_stop
    00> @@@ ble_radio_notification_init(87)->sd_radio_notification_cfg_set
    00> @@@ flags_set(309)->sd_ble_gap_adv_set_configure
    00> @@@ ble_advertising_start(754)->sd_ble_gap_adv_set_configure
    00> @@@ ble_advertising_start(759)->sd_ble_gap_adv_start
    00> 03:29:35.6688  BLE_ADV_EVT_IDLE(0)
    00> 03:29:36.6667  > Auth Buzzer timeout.
    00> 
    00> *** No radio notification for a while(2000ms).
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> *** SCAN START ***
    00> 
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> @@@ MdlBLE_vd_AdvertisingStopReq(2570)->sd_ble_gap_adv_stop
    00> @@@ ble_radio_notification_init(87)->sd_radio_notification_cfg_set
    00> @@@ flags_set(309)->sd_ble_gap_adv_set_configure
    00> @@@ ble_advertising_start(754)->sd_ble_gap_adv_set_configure
    00> @@@ ble_advertising_start(759)->sd_ble_gap_adv_start
    00> 03:29:36.6688  BLE_ADV_EVT_IDLE(0)
    00> *** No radio notification for a while(3000ms).
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> *** SCAN START ***
    00> 
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> @@@ MdlBLE_vd_AdvertisingStopReq(2570)->sd_ble_gap_adv_stop
    00> @@@ ble_radio_notification_init(87)->sd_radio_notification_cfg_set
    00> @@@ flags_set(309)->sd_ble_gap_adv_set_configure
    00> @@@ ble_advertising_start(754)->sd_ble_gap_adv_set_configure
    00> @@@ ble_advertising_start(759)->sd_ble_gap_adv_start
    00> 03:29:37.6687  BLE_ADV_EVT_IDLE(0)
    00> *** No radio notification for a while(4000ms).
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> *** SCAN START ***
    00> 
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> @@@ MdlBLE_vd_AdvertisingStopReq(2570)->sd_ble_gap_adv_stop
    00> @@@ ble_radio_notification_init(87)->sd_radio_notification_cfg_set
    00> @@@ flags_set(309)->sd_ble_gap_adv_set_configure
    00> @@@ ble_advertising_start(754)->sd_ble_gap_adv_set_configure
    00> @@@ ble_advertising_start(759)->sd_ble_gap_adv_start
    00> 03:29:38.6688  BLE_ADV_EVT_IDLE(0)
    00> *** No radio notification for a while(5000ms).
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> *** SCAN START ***
    00> 
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> @@@ MdlBLE_vd_AdvertisingStopReq(2570)->sd_ble_gap_adv_stop
    00> @@@ ble_radio_notification_init(87)->sd_radio_notification_cfg_set
    00> @@@ flags_set(309)->sd_ble_gap_adv_set_configure
    00> @@@ ble_advertising_start(754)->sd_ble_gap_adv_set_configure
    00> @@@ ble_advertising_start(759)->sd_ble_gap_adv_start
    00> 03:29:39.6688  BLE_ADV_EVT_IDLE(0)
    00> *** No radio notification for a while(6000ms).
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> *** SCAN START ***
    00> 
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> @@@ MdlBLE_vd_AdvertisingStopReq(2570)->sd_ble_gap_adv_stop
    00> @@@ ble_radio_notification_init(87)->sd_radio_notification_cfg_set
    00> @@@ flags_set(309)->sd_ble_gap_adv_set_configure
    00> @@@ ble_advertising_start(754)->sd_ble_gap_adv_set_configure
    00> @@@ ble_advertising_start(759)->sd_ble_gap_adv_start
    00> 03:29:40.6690  BLE_ADV_EVT_IDLE(0)
    00> *** No radio notification for a while(7000ms).
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> *** SCAN START ***
    00> 
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> @@@ MdlBLE_vd_AdvertisingStopReq(2570)->sd_ble_gap_adv_stop
    00> @@@ ble_radio_notification_init(87)->sd_radio_notification_cfg_set
    00> @@@ flags_set(309)->sd_ble_gap_adv_set_configure
    00> @@@ ble_advertising_start(754)->sd_ble_gap_adv_set_configure
    00> @@@ ble_advertising_start(759)->sd_ble_gap_adv_start
    00> 03:29:41.6689  BLE_ADV_EVT_IDLE(0)
    00> *** No radio notification for a while(8000ms).
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> *** SCAN START ***
    00> 
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> @@@ MdlBLE_vd_AdvertisingStopReq(2570)->sd_ble_gap_adv_stop
    00> @@@ ble_radio_notification_init(87)->sd_radio_notification_cfg_set
    00> @@@ flags_set(309)->sd_ble_gap_adv_set_configure
    00> @@@ ble_advertising_start(754)->sd_ble_gap_adv_set_configure
    00> @@@ ble_advertising_start(759)->sd_ble_gap_adv_start
    00> 03:29:42.6689  BLE_ADV_EVT_IDLE(0)
    00> *** No radio notification for a while(9000ms).
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> *** SCAN START ***
    00> 
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> @@@ MdlBLE_vd_AdvertisingStopReq(2570)->sd_ble_gap_adv_stop
    00> @@@ ble_radio_notification_init(87)->sd_radio_notification_cfg_set
    00> @@@ flags_set(309)->sd_ble_gap_adv_set_configure
    00> @@@ ble_advertising_start(754)->sd_ble_gap_adv_set_configure
    00> @@@ ble_advertising_start(759)->sd_ble_gap_adv_start
    00> 03:29:43.6689  BLE_ADV_EVT_IDLE(0)
    00> *** No radio notification for a while(10000ms).
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> *** SCAN START ***
    00> 
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> @@@ MdlBLE_vd_AdvertisingStopReq(2570)->sd_ble_gap_adv_stop
    00> @@@ ble_radio_notification_init(87)->sd_radio_notification_cfg_set
    00> @@@ flags_set(309)->sd_ble_gap_adv_set_configure
    00> @@@ ble_advertising_start(754)->sd_ble_gap_adv_set_configure
    00> @@@ ble_advertising_start(759)->sd_ble_gap_adv_start
    00> 03:29:44.6689  BLE_ADV_EVT_IDLE(0)
    00> *** No radio notification for a while(11000ms).
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> *** SCAN START ***
    00> 
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> @@@ MdlBLE_vd_AdvertisingStopReq(2570)->sd_ble_gap_adv_stop
    00> @@@ ble_radio_notification_init(87)->sd_radio_notification_cfg_set
    00> @@@ flags_set(309)->sd_ble_gap_adv_set_configure
    00> @@@ ble_advertising_start(754)->sd_ble_gap_adv_set_configure
    00> @@@ ble_advertising_start(759)->sd_ble_gap_adv_start
    00> 03:29:45.6689  BLE_ADV_EVT_IDLE(0)
    00> *** No radio notification for a while(12000ms).
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> *** SCAN START ***
    00> 
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> @@@ MdlBLE_vd_AdvertisingStopReq(2570)->sd_ble_gap_adv_stop
    00> @@@ ble_radio_notification_init(87)->sd_radio_notification_cfg_set
    00> @@@ flags_set(309)->sd_ble_gap_adv_set_configure
    00> @@@ ble_advertising_start(754)->sd_ble_gap_adv_set_configure
    00> @@@ ble_advertising_start(759)->sd_ble_gap_adv_start
    00> 03:29:46.6689  BLE_ADV_EVT_IDLE(0)
    00> *** No radio notification for a while(13000ms).
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> *** SCAN START ***
    00> 
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> @@@ MdlBLE_vd_AdvertisingStopReq(2570)->sd_ble_gap_adv_stop
    00> @@@ ble_radio_notification_init(87)->sd_radio_notification_cfg_set
    00> @@@ flags_set(309)->sd_ble_gap_adv_set_configure
    00> @@@ ble_advertising_start(754)->sd_ble_gap_adv_set_configure
    00> @@@ ble_advertising_start(759)->sd_ble_gap_adv_start
    00> 03:29:47.6689  BLE_ADV_EVT_IDLE(0)
    00> *** No radio notification for a while(14000ms).
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> *** SCAN START ***
    00> 
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> @@@ MdlBLE_vd_AdvertisingStopReq(2570)->sd_ble_gap_adv_stop
    00> @@@ ble_radio_notification_init(87)->sd_radio_notification_cfg_set
    00> @@@ flags_set(309)->sd_ble_gap_adv_set_configure
    00> @@@ ble_advertising_start(754)->sd_ble_gap_adv_set_configure
    00> @@@ ble_advertising_start(759)->sd_ble_gap_adv_start
    00> 03:29:48.6689  BLE_ADV_EVT_IDLE(0)
    00> *** No radio notification for a while(15000ms).
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> *** SCAN START ***
    00> 
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> @@@ MdlBLE_vd_AdvertisingStopReq(2570)->sd_ble_gap_adv_stop
    00> @@@ ble_radio_notification_init(87)->sd_radio_notification_cfg_set
    00> @@@ flags_set(309)->sd_ble_gap_adv_set_configure
    00> @@@ ble_advertising_start(754)->sd_ble_gap_adv_set_configure
    00> @@@ ble_advertising_start(759)->sd_ble_gap_adv_start
    00> 03:29:49.6690  BLE_ADV_EVT_IDLE(0)
    00> *** No radio notification for a while(16000ms).
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> *** SCAN START ***
    00> 
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> @@@ MdlBLE_vd_AdvertisingStopReq(2570)->sd_ble_gap_adv_stop
    00> @@@ ble_radio_notification_init(87)->sd_radio_notification_cfg_set
    00> @@@ flags_set(309)->sd_ble_gap_adv_set_configure
    00> @@@ ble_advertising_start(754)->sd_ble_gap_adv_set_configure
    00> @@@ ble_advertising_start(759)->sd_ble_gap_adv_start
    00> 03:29:50.6690  BLE_ADV_EVT_IDLE(0)
    00> *** No radio notification for a while(17000ms).
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> *** SCAN START ***
    00> 
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> @@@ MdlBLE_vd_AdvertisingStopReq(2570)->sd_ble_gap_adv_stop
    00> @@@ ble_radio_notification_init(87)->sd_radio_notification_cfg_set
    00> @@@ flags_set(309)->sd_ble_gap_adv_set_configure
    00> @@@ ble_advertising_start(754)->sd_ble_gap_adv_set_configure
    00> @@@ ble_advertising_start(759)->sd_ble_gap_adv_start
    00> 03:29:51.6691  BLE_ADV_EVT_IDLE(0)
    00> *** No radio notification for a while(18000ms).
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> *** SCAN START ***
    00> 
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> @@@ MdlBLE_vd_AdvertisingStopReq(2570)->sd_ble_gap_adv_stop
    00> @@@ ble_radio_notification_init(87)->sd_radio_notification_cfg_set
    00> @@@ flags_set(309)->sd_ble_gap_adv_set_configure
    00> @@@ ble_advertising_start(754)->sd_ble_gap_adv_set_configure
    00> @@@ ble_advertising_start(759)->sd_ble_gap_adv_start
    00> 03:29:52.6690  BLE_ADV_EVT_IDLE(0)
    00> *** No radio notification for a while(19000ms).
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> *** SCAN START ***
    00> 
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> @@@ MdlBLE_vd_AdvertisingStopReq(2570)->sd_ble_gap_adv_stop
    00> @@@ ble_radio_notification_init(87)->sd_radio_notification_cfg_set
    00> @@@ flags_set(309)->sd_ble_gap_adv_set_configure
    00> @@@ ble_advertising_start(754)->sd_ble_gap_adv_set_configure
    00> @@@ ble_advertising_start(759)->sd_ble_gap_adv_start
    00> 03:29:53.6690  BLE_ADV_EVT_IDLE(0)
    00> *** No radio notification for a while(20000ms).
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> *** SCAN START ***
    00> 
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> @@@ MdlBLE_vd_AdvertisingStopReq(2570)->sd_ble_gap_adv_stop
    00> @@@ ble_radio_notification_init(87)->sd_radio_notification_cfg_set
    00> @@@ flags_set(309)->sd_ble_gap_adv_set_configure
    00> @@@ ble_advertising_start(754)->sd_ble_gap_adv_set_configure
    00> @@@ ble_advertising_start(759)->sd_ble_gap_adv_start
    00> 03:29:54.6690  BLE_ADV_EVT_IDLE(0)
    00> *** No radio notification for a while(21000ms).
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> *** SCAN START ***
    00> 
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> @@@ MdlBLE_vd_AdvertisingStopReq(2570)->sd_ble_gap_adv_stop
    00> @@@ ble_radio_notification_init(87)->sd_radio_notification_cfg_set
    00> @@@ flags_set(309)->sd_ble_gap_adv_set_configure
    00> @@@ ble_advertising_start(754)->sd_ble_gap_adv_set_configure
    00> @@@ ble_advertising_start(759)->sd_ble_gap_adv_start
    00> 03:29:55.6690  BLE_ADV_EVT_IDLE(0)
    00> *** No radio notification for a while(22000ms).
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> *** SCAN START ***
    00> 
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> @@@ MdlBLE_vd_AdvertisingStopReq(2570)->sd_ble_gap_adv_stop
    00> @@@ ble_radio_notification_init(87)->sd_radio_notification_cfg_set
    00> @@@ flags_set(309)->sd_ble_gap_adv_set_configure
    00> @@@ ble_advertising_start(754)->sd_ble_gap_adv_set_configure
    00> @@@ ble_advertising_start(759)->sd_ble_gap_adv_start
    00> 03:29:56.6691  BLE_ADV_EVT_IDLE(0)
    00> *** No radio notification for a while(23000ms).
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> *** SCAN START ***
    00> 
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> @@@ MdlBLE_vd_AdvertisingStopReq(2570)->sd_ble_gap_adv_stop
    00> @@@ ble_radio_notification_init(87)->sd_radio_notification_cfg_set
    00> @@@ flags_set(309)->sd_ble_gap_adv_set_configure
    00> @@@ ble_advertising_start(754)->sd_ble_gap_adv_set_configure
    00> @@@ ble_advertising_start(759)->sd_ble_gap_adv_start
    00> 03:29:57.6691  BLE_ADV_EVT_IDLE(0)
    00> *** No radio notification for a while(24000ms).
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> *** SCAN START ***
    00> 
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> @@@ MdlBLE_vd_AdvertisingStopReq(2570)->sd_ble_gap_adv_stop
    00> @@@ ble_radio_notification_init(87)->sd_radio_notification_cfg_set
    00> @@@ flags_set(309)->sd_ble_gap_adv_set_configure
    00> @@@ ble_advertising_start(754)->sd_ble_gap_adv_set_configure
    00> @@@ ble_advertising_start(759)->sd_ble_gap_adv_start
    00> 03:29:58.6691  BLE_ADV_EVT_IDLE(0)
    00> *** No radio notification for a while(25000ms).
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> *** SCAN START ***
    00> 
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> @@@ MdlBLE_vd_AdvertisingStopReq(2570)->sd_ble_gap_adv_stop
    00> @@@ ble_radio_notification_init(87)->sd_radio_notification_cfg_set
    00> @@@ flags_set(309)->sd_ble_gap_adv_set_configure
    00> @@@ ble_advertising_start(754)->sd_ble_gap_adv_set_configure
    00> @@@ ble_advertising_start(759)->sd_ble_gap_adv_start
    00> 03:29:59.6691  BLE_ADV_EVT_IDLE(0)
    00> *** No radio notification for a while(26000ms).
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> *** SCAN START ***
    00> 
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> @@@ MdlBLE_vd_AdvertisingStopReq(2570)->sd_ble_gap_adv_stop
    00> @@@ ble_radio_notification_init(87)->sd_radio_notification_cfg_set
    00> @@@ flags_set(309)->sd_ble_gap_adv_set_configure
    00> @@@ ble_advertising_start(754)->sd_ble_gap_adv_set_configure
    00> @@@ ble_advertising_start(759)->sd_ble_gap_adv_start
    00> 03:30:00.6691  BLE_ADV_EVT_IDLE(0)
    00> *** No radio notification for a while(27000ms).
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> *** SCAN START ***
    00> 
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> @@@ MdlBLE_vd_AdvertisingStopReq(2570)->sd_ble_gap_adv_stop
    00> @@@ ble_radio_notification_init(87)->sd_radio_notification_cfg_set
    00> @@@ flags_set(309)->sd_ble_gap_adv_set_configure
    00> @@@ ble_advertising_start(754)->sd_ble_gap_adv_set_configure
    00> @@@ ble_advertising_start(759)->sd_ble_gap_adv_start
    00> 03:30:01.6691  BLE_ADV_EVT_IDLE(0)
    00> *** No radio notification for a while(28000ms).
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> *** SCAN START ***
    00> 
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> @@@ MdlBLE_vd_AdvertisingStopReq(2570)->sd_ble_gap_adv_stop
    00> @@@ ble_radio_notification_init(87)->sd_radio_notification_cfg_set
    00> @@@ flags_set(309)->sd_ble_gap_adv_set_configure
    00> @@@ ble_advertising_start(754)->sd_ble_gap_adv_set_configure
    00> @@@ ble_advertising_start(759)->sd_ble_gap_adv_start
    00> 03:30:02.6692  BLE_ADV_EVT_IDLE(0)
    00> *** No radio notification for a while(29000ms).
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> *** SCAN START ***
    00> 
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> @@@ MdlBLE_vd_AdvertisingStopReq(2570)->sd_ble_gap_adv_stop
    00> @@@ ble_radio_notification_init(87)->sd_radio_notification_cfg_set
    00> @@@ flags_set(309)->sd_ble_gap_adv_set_configure
    00> @@@ ble_advertising_start(754)->sd_ble_gap_adv_set_configure
    00> @@@ ble_advertising_start(759)->sd_ble_gap_adv_start
    00> 03:30:03.6691  BLE_ADV_EVT_IDLE(0)
    00> <error> app: ERROR 0 [NRF_SUCCESS] at D:\SVN\BLE_MockUp\BLE_Module\src\Middleware\MdlBLE.c:1532
    00> 
    00> PC at: 0x000357CF
    00> 
    00> <error> app: End of error report
    00> 
    
    # Logging stopped @ 11 Jul 2024 09:00:29
    

    When this happens, the only thing that can be thought of is that the SoftDevice is locked.

    The only other thing that can be done is to try stopping and restarting the SoftDevice itself, but since it is not clear what state the SoftDevice is in, a self-reset may be more reliable.

    Best regards.

  • Hi hiroiwas,

    Thank you for the detailed information.

    I highly doubt that the SoftDevice drops event, and even if it does, I strongly believe it cannot be something important like BLE_GAT_EVT_CONNECTED. Since the data you have provided so far does indicate this, I will start an internal query with the past SoftDevice team to be extra sure.

    Your latest log doesn't highlight what sd_ble_gap_adv_start() returns. Are we sure that it returns 0?

    Also, I don't see a scan starting attempted. 

    I noticed that here we have only been looking into BLE_GAP_EVT_CONNECTED. However, that is not the only outcome from a connection establishment attempt. The attempt could also fail with BLE_GAP_EVT_TIMEOUT with ble_gap_evt_timeout_t::src == BLE_GAP_TIMEOUT_SRC_CONN. Has this case been checked?

    Finally, when event drops are being suspected, using Radio Notification might make the matter worse.

    For the purpose of resetting the device as a fail-safe, then I agree that you need Radio Notification for that.

    But for the purpose of debugging, if we consider our goal resolving the issue completely, and be free of Radio Notification, then you might want to bind RADIO events to GPIOTE output with PPI and keep track of it instead. I have some sample snippets here: https://gist.github.com/hieuv/06fb6b9609c59e3a57bb62340ccaf242.

    Best regards,

    Hieu

    P.s: At the end of your SoftDevice event handler, could you please also add a default case handling where it just quickly log what the value of the event type is? This helps us check if there are any events we haven't accounted for.

    Also, I highly recommend using the Logger Module with NRF_LOG_DEFERRED, if you are not using it yet. Adding timestamp, no matter how basic, also helps getting more information into the log. 

  • Hello Hieu,


    > Your latest log doesn't highlight what sd_ble_gap_adv_start() returns. Are we sure that it returns 0?

    The return value of SoftDevice was not output.
    I will add an output and check it.


    > Also, I don't see a scan starting attempted.

    sd_ble_gap_scan_start()  is deter because of the large number of log outputs.
    SD_BLE_GAP_ADV_START() is unconditionally called after nrf_ble_scan_stop() in nrf_ble_scan_start(), so I think there is no doubt.


    > BLE_GAP_TIMEOUT_SRC_CONN. Has this case been checked?

    On the log, it was confirmed that BLE_GAP_TIMEOUT_SRC_CONN has never occurred as an event.
    Currently, BLE_GAP_TIMEOUT_SRC_CONN does nothing except to log, but is it better to cut and re -scan?


    > you might want to bind RADIO events to GPIOTE output with PPI and keep track of it instead.

    Does it mean monitoring the Radio status using a logic analyzer, etc., without using the Radio Notification event?

    Okay, I'll try it.


    > At the end of your SoftDevice event handler, could you please also add a default case handling where it just quickly log what the value of the event type is?

    Does this mean that the following log output is enabled?

    nrf_sdh_soc.c(87) NRF_LOG_DEBUG("SoC event: 0x%x.", evt_id);

    Or do you mean adding an observer that logs?


    > Also, I highly recommend using the Logger Module with NRF_LOG_DEFERRED,

    Thanks for the advice, I wasn't using that, I'll set it.


    > Adding timestamp, no matter how basic, also helps getting more information into the log.

    Log it as NRF_LOG_INIT( app_timer_cnt_get );


    I will report back if the problem occurs again.


    Best regards.

  • hiroiwas said:
    > At the end of your SoftDevice event handler, could you please also add a default case handling where it just quickly log what the value of the event type is?

    Does this mean that the following log output is enabled?

    nrf_sdh_soc.c(87) NRF_LOG_DEBUG("SoC event: 0x%x.", evt_id);

    Or do you mean adding an observer that logs?

    I am not certain if the event polling in nrf_sdh_soc.c is the same, but I figure it doesn't hurt to enable it too.

    What I meant is to add handling to your equivalent of the ble_evt_handler in the ble_app_uart example.

    Looking forwards to your further test results.

    Best regards,

    Hieu

Related