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.

Parents
  • Hi,

    Advertising should not just stop by itself. Could it be that a connection was established but in some special cases you do not re-start advertising, for instance? Do you have logging on the device that can shead some information on this?

    As for a workaround, you are right about radio notifications. That will only tell you when the radio is active, but not for what. I would of course suggest to find the root cause and fix that, but as a workaround perhaps you could regularily stop and re-start advertising?

  • Hello,  Einar.

    Sorry for the slight delay in responding due to low reproducibility and another task.

    Subsequent investigation revealed that when this issue occurs, the signal does not reach Radio Notification, so not only advertising but also RADIO stops.

    Attached are excerpt logs, a HEX dump, and a RAM dump from when the problem occurred.
    The heap is initialized with a 1KB incrementing fill pattern, and the stack is initialized with 0xCC by INITIALIZE_STACK.

    Log of the incident.zip

    SD is s140 v7.3.0, the SDK is 17.1.0_ddde560, and the build environment is SES V5.44.

    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

  • Hello Hieu,

    Since the problem occurred, I have attached the trimmed raw log.

    00> ==SCAN_RSP== AdType:FF
    00> 
    00>  42 04 01 00 00 00 00 0B  55 55 55 55 00 DF C3 10  FF 0E 2F B7 F5 66 99 D6  54 0C EE C2 01
    00> 00:07:46.5214  > Continue moving average calculation with RssiList[1]
    00> 
    00> > Addr:57:6A:99:32:FA:2B (Resolvable) RSSI:-49dBm(+0) raw:-49dBm
    00> 
    00> > Suppress re-auth: elapsed 1645ms.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> > Code:55555555 UID:000-00000011 Rssi+0 Ver.1
    00> 
    00> 
    00> ==SCAN_RSP== AdType:FF
    00> 
    00>  42 04 01 00 00 00 00 0B  55 55 55 55 00 1B B8 9E  63 04 B0 F4 F4 66 99 D6  55 0C EE C3 01
    00> 00:07:46.7956  > Continue moving average calculation with RssiList[1]
    00> 
    00> > Addr:57:6A:99:32:FA:2B (Resolvable) RSSI:-48dBm(+0) raw:-48dBm
    00> 
    00> > Suppress re-auth: elapsed 1919ms.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> 00:07:46.8769  > 55555555-000-00000011/71:32:4C:9B:07:56 (Resolvable) was removed from the authentication suppression list, can auth: elapsed 2000ms.
    00> 
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> > Code:55555555 UID:000-00000011 Rssi+0 Ver.1
    00> 
    00> 
    00> ==SCAN_RSP== AdType:FF
    00> 
    00>  42 04 01 00 00 00 00 0B  55 55 55 55 00 1B B8 9E  63 04 B0 F4 F4 66 99 D6  55 0C EE C3 01
    00> 00:07:46.9318  > Continue moving average calculation with RssiList[1]
    00> 
    00> > Addr:57:6A:99:32:FA:2B (Resolvable) RSSI:-44dBm(+0) raw:-44dBm
    00> 
    00> > TicketSeedBase:(16)
    00>  55 55 55 55 00 00 00 00  0B 66 8C E7 92 00 00 00
    00> > AccInfo[0] Accumulate.
    00> 
    00> > - Authed #105 at Fri Jul 19 02:58:33 2024.
    00> 
    00> > - Addr: 57:6A:99:32:FA:2B (Resolvable) (000-00000011)
    00> 
    00> > - RSSI: -44dBm(+0)
    00> 
    00> > - Auth: 1
    00> 
    00> +++ CERT OK +++ (RSSI: -44)
    00> 
    00> 
    00> > Device has been added to the authentication suppression list, can NOT auth.
    00> 
    00> 
    00> 00:07:46.9358  > All Smartphone Suppression timer start.
    00> 
    00> *** SCAN STOP ***
    00> 
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> UART-Tx:(41)
    00>  F2 01 10 10 11 00 05 55  55 55 51 60 00 00 00 00  00 00 00 11 2C 00 00 00  00 0B FF EE C3 1B B8 9E
    00>  63 04 55 55 55 55 00 01  00
    00> UART-Rx:(2)
    00>  F3 01
    00> <debug> ser_conn: [SD_CALL]:SD_CALL_UNKNOWN
    00> 
    00> 00:07:47.0361  > All Smartphone Suppression timer has ended.
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> <debug> ble_scan: Scanning parameters have been changed successfully
    00> 
    00> *** SCAN START ***
    00> 
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> <debug> ble_scan: Scanning
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> > Code:55555555 UID:000-00000011 Rssi+0 Ver.1
    00> 
    00> 
    00> ==SCAN_RSP== AdType:FF
    00> 
    00>  42 04 01 00 00 00 00 0B  55 55 55 55 00 1B B8 9E  63 04 B0 F4 F4 66 99 D6  55 0C EE C3 01
    00> 00:07:47.2010  > Continue moving average calculation with RssiList[1]
    00> 
    00> > Addr:57:6A:99:32:FA:2B (Resolvable) RSSI:-46dBm(+0) raw:-46dBm
    00> 
    00> > Suppress re-auth: elapsed 266ms.
    00> 
    00> 00:07:47.2018  > 1BACC0DE-50273-09551615/71:32:4C:9B:07:56 (Resolvable) was removed from the rssi moving average buffering list, calc end: elapsed 1001ms.
    00> 
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> 
    00> ==SCAN_RSP== AdType:FF
    00> 
    00>  4C 00 01 00 00 00 00 0B  55 55 00 53 00 45 00 43  4F 02 4D
    00> 00:07:47.2170  > Start moving average calculation with RssiList[0]
    00> 
    00> > Addr:71:32:4C:9B:07:56 (Resolvable) RSSI:-42dBm(+0) raw:-42dBm
    00> 
    00> > No accumulated.
    00> 
    00> 
    00> @@@ scan_connect_judgement(688)->sd_ble_gap_connect
    00> +++ Connecting +++
    00> 
    00> 00:07:47.4373  > Auth Buzzer timeout.
    00> 
    00> 00:07:48.2013  > 55555555-000-00000011/57:6A:99:32:FA:2B (Resolvable) was removed from the rssi moving average buffering list, calc end: elapsed 1000ms.
    00> 
    00> 
    00> 00:07:48.2173  > 1BACC0DE-50273-09551615/71:32:4C:9B:07:56 (Resolvable) was removed from the rssi moving average buffering list, calc end: elapsed 1000ms.
    00> 
    00> 
    00> *** No radio notification for a while(1000ms).
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> <debug> ble_scan: Scanning parameters have been changed successfully
    00> 
    00> *** SCAN START ***
    00> 
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> <debug> ble_scan: Scanning
    00> 
    00> @@@ MdlBLE_vd_AdvertisingStopReq(2666)->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> sd_ble_gap_adv_start() returned NRF_SUCCESS.00:07:48.2378  BLE_ADV_EVT_IDLE(0)
    00> 00:07:48.9356  > 55555555-000-00000011/57:6A:99:32:FA:2B (Resolvable) was removed from the authentication suppression list, can auth: elapsed 2000ms.
    00> 
    00> 
    00> *** No radio notification for a while(2000ms).
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> <debug> ble_scan: Scanning parameters have been changed successfully
    00> 
    00> *** SCAN START ***
    00> 
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> <debug> ble_scan: Scanning
    00> 
    00> @@@ MdlBLE_vd_AdvertisingStopReq(2666)->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> sd_ble_gap_adv_start() returned NRF_SUCCESS.00:07:49.2378  BLE_ADV_EVT_IDLE(0)


    The addition of SoftDevice events is causing a large number of logs to be output.

    As an aside, this causes nrf_log to hang and the same log to be output repeatedly, so I have to manually reset it each time.
    Reference link: devzone.nordicsemi.com/.../nrf_log-output-sometimes-goes-crazy
    It looks like this issue is still not resolved.

    The problem begins at L.322, one second before L.346 "*** No radio notification", and it seems that the SoftDevice is unresponsive and locked in response to sd_ble_gap_connect.

    Please let me know if there is any other information you need.

    p.s.
    I tried to upload a log, but even after compressing it, I got the message "File type is not allowed" and it didn't work.
    I think there is a size limit, but how large can I upload?

    Best regards.

Reply
  • Hello Hieu,

    Since the problem occurred, I have attached the trimmed raw log.

    00> ==SCAN_RSP== AdType:FF
    00> 
    00>  42 04 01 00 00 00 00 0B  55 55 55 55 00 DF C3 10  FF 0E 2F B7 F5 66 99 D6  54 0C EE C2 01
    00> 00:07:46.5214  > Continue moving average calculation with RssiList[1]
    00> 
    00> > Addr:57:6A:99:32:FA:2B (Resolvable) RSSI:-49dBm(+0) raw:-49dBm
    00> 
    00> > Suppress re-auth: elapsed 1645ms.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> > Code:55555555 UID:000-00000011 Rssi+0 Ver.1
    00> 
    00> 
    00> ==SCAN_RSP== AdType:FF
    00> 
    00>  42 04 01 00 00 00 00 0B  55 55 55 55 00 1B B8 9E  63 04 B0 F4 F4 66 99 D6  55 0C EE C3 01
    00> 00:07:46.7956  > Continue moving average calculation with RssiList[1]
    00> 
    00> > Addr:57:6A:99:32:FA:2B (Resolvable) RSSI:-48dBm(+0) raw:-48dBm
    00> 
    00> > Suppress re-auth: elapsed 1919ms.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> 00:07:46.8769  > 55555555-000-00000011/71:32:4C:9B:07:56 (Resolvable) was removed from the authentication suppression list, can auth: elapsed 2000ms.
    00> 
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> > Code:55555555 UID:000-00000011 Rssi+0 Ver.1
    00> 
    00> 
    00> ==SCAN_RSP== AdType:FF
    00> 
    00>  42 04 01 00 00 00 00 0B  55 55 55 55 00 1B B8 9E  63 04 B0 F4 F4 66 99 D6  55 0C EE C3 01
    00> 00:07:46.9318  > Continue moving average calculation with RssiList[1]
    00> 
    00> > Addr:57:6A:99:32:FA:2B (Resolvable) RSSI:-44dBm(+0) raw:-44dBm
    00> 
    00> > TicketSeedBase:(16)
    00>  55 55 55 55 00 00 00 00  0B 66 8C E7 92 00 00 00
    00> > AccInfo[0] Accumulate.
    00> 
    00> > - Authed #105 at Fri Jul 19 02:58:33 2024.
    00> 
    00> > - Addr: 57:6A:99:32:FA:2B (Resolvable) (000-00000011)
    00> 
    00> > - RSSI: -44dBm(+0)
    00> 
    00> > - Auth: 1
    00> 
    00> +++ CERT OK +++ (RSSI: -44)
    00> 
    00> 
    00> > Device has been added to the authentication suppression list, can NOT auth.
    00> 
    00> 
    00> 00:07:46.9358  > All Smartphone Suppression timer start.
    00> 
    00> *** SCAN STOP ***
    00> 
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> UART-Tx:(41)
    00>  F2 01 10 10 11 00 05 55  55 55 51 60 00 00 00 00  00 00 00 11 2C 00 00 00  00 0B FF EE C3 1B B8 9E
    00>  63 04 55 55 55 55 00 01  00
    00> UART-Rx:(2)
    00>  F3 01
    00> <debug> ser_conn: [SD_CALL]:SD_CALL_UNKNOWN
    00> 
    00> 00:07:47.0361  > All Smartphone Suppression timer has ended.
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> <debug> ble_scan: Scanning parameters have been changed successfully
    00> 
    00> *** SCAN START ***
    00> 
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> <debug> ble_scan: Scanning
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> > Code:55555555 UID:000-00000011 Rssi+0 Ver.1
    00> 
    00> 
    00> ==SCAN_RSP== AdType:FF
    00> 
    00>  42 04 01 00 00 00 00 0B  55 55 55 55 00 1B B8 9E  63 04 B0 F4 F4 66 99 D6  55 0C EE C3 01
    00> 00:07:47.2010  > Continue moving average calculation with RssiList[1]
    00> 
    00> > Addr:57:6A:99:32:FA:2B (Resolvable) RSSI:-46dBm(+0) raw:-46dBm
    00> 
    00> > Suppress re-auth: elapsed 266ms.
    00> 
    00> 00:07:47.2018  > 1BACC0DE-50273-09551615/71:32:4C:9B:07:56 (Resolvable) was removed from the rssi moving average buffering list, calc end: elapsed 1001ms.
    00> 
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> <debug> nrf_sdh_ble: BLE event: 0x1D.
    00> 
    00> 
    00> ==SCAN_RSP== AdType:FF
    00> 
    00>  4C 00 01 00 00 00 00 0B  55 55 00 53 00 45 00 43  4F 02 4D
    00> 00:07:47.2170  > Start moving average calculation with RssiList[0]
    00> 
    00> > Addr:71:32:4C:9B:07:56 (Resolvable) RSSI:-42dBm(+0) raw:-42dBm
    00> 
    00> > No accumulated.
    00> 
    00> 
    00> @@@ scan_connect_judgement(688)->sd_ble_gap_connect
    00> +++ Connecting +++
    00> 
    00> 00:07:47.4373  > Auth Buzzer timeout.
    00> 
    00> 00:07:48.2013  > 55555555-000-00000011/57:6A:99:32:FA:2B (Resolvable) was removed from the rssi moving average buffering list, calc end: elapsed 1000ms.
    00> 
    00> 
    00> 00:07:48.2173  > 1BACC0DE-50273-09551615/71:32:4C:9B:07:56 (Resolvable) was removed from the rssi moving average buffering list, calc end: elapsed 1000ms.
    00> 
    00> 
    00> *** No radio notification for a while(1000ms).
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> <debug> ble_scan: Scanning parameters have been changed successfully
    00> 
    00> *** SCAN START ***
    00> 
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> <debug> ble_scan: Scanning
    00> 
    00> @@@ MdlBLE_vd_AdvertisingStopReq(2666)->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> sd_ble_gap_adv_start() returned NRF_SUCCESS.00:07:48.2378  BLE_ADV_EVT_IDLE(0)
    00> 00:07:48.9356  > 55555555-000-00000011/57:6A:99:32:FA:2B (Resolvable) was removed from the authentication suppression list, can auth: elapsed 2000ms.
    00> 
    00> 
    00> *** No radio notification for a while(2000ms).
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> <debug> ble_scan: Scanning parameters have been changed successfully
    00> 
    00> *** SCAN START ***
    00> 
    00> 
    00> @@@ nrf_ble_scan_stop(1041)->sd_ble_gap_scan_stop
    00> <debug> ble_scan: Scanning
    00> 
    00> @@@ MdlBLE_vd_AdvertisingStopReq(2666)->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> sd_ble_gap_adv_start() returned NRF_SUCCESS.00:07:49.2378  BLE_ADV_EVT_IDLE(0)


    The addition of SoftDevice events is causing a large number of logs to be output.

    As an aside, this causes nrf_log to hang and the same log to be output repeatedly, so I have to manually reset it each time.
    Reference link: devzone.nordicsemi.com/.../nrf_log-output-sometimes-goes-crazy
    It looks like this issue is still not resolved.

    The problem begins at L.322, one second before L.346 "*** No radio notification", and it seems that the SoftDevice is unresponsive and locked in response to sd_ble_gap_connect.

    Please let me know if there is any other information you need.

    p.s.
    I tried to upload a log, but even after compressing it, I got the message "File type is not allowed" and it didn't work.
    I think there is a size limit, but how large can I upload?

    Best regards.

Children
No Data
Related