BLE scan does not timeout

[Prashant Ambardekar]

I am using NRF 52840 dongle, SoftDevice 3.1 and connectivity firmware 1.2.3. I have a node js application, I am using pc-ble-driver-js 2.4.3. I am testing the application on Windows 10 32-bit.

The app starts the scan for 3 seconds every 6 seconds. For first 15-20 minutes or so, scan starts and times out correctly after 3 seconds. But after that the scan does not time out at all. Due to this subsequent scans starts fail with NRF_ERROR_BUSY.

I can introduce an explicit stop scan if timeout does not happen. But I wanted to check if this is a known issue or a misconfiguration on my part. I use following scan parameters.

const scanParameters = { active: true, interval: 100, window: 20, timeout: 3 };

Debug logs show following pattern

[2018-11-20 12:26:56.853] [info] Starting BLE scan
[2018-11-20 12:26:59.891] [info] ###NRF_Log: 1: GAP_EVT_TIMEOUT time:2018-11-20T06:56:59.892Z connHandle:65535 src:2 srcName:bleGapTimeoutSrcScan
[2018-11-20 12:27:02.882] [info] Starting BLE scan
[2018-11-20 12:27:05.972] [info] ###NRF_Log: 1: GAP_EVT_TIMEOUT time:2018-11-20T06:57:05.973Z connHandle:65535 src:2 srcName:bleGapTimeoutSrcScan
[2018-11-20 12:27:08.913] [info] Starting BLE scan
[2018-11-20 12:27:11.952] [info] ###NRF_Log: 1: GAP_EVT_TIMEOUT time:2018-11-20T06:57:11.952Z connHandle:65535 src:2 srcName:bleGapTimeoutSrcScan
[2018-11-20 12:27:14.931] [info] Starting BLE scan
[2018-11-20 12:27:17.972] [info] ###NRF_Log: 1: GAP_EVT_TIMEOUT time:2018-11-20T06:57:17.973Z connHandle:65535 src:2 srcName:bleGapTimeoutSrcScan
[2018-11-20 12:27:20.933] [info] Starting BLE scan
[2018-11-20 12:27:24.006] [info] ###NRF_Log: 1: GAP_EVT_TIMEOUT time:2018-11-20T06:57:24.003Z connHandle:65535 src:2 srcName:bleGapTimeoutSrcScan
[2018-11-20 12:27:26.962] [info] Starting BLE scan
[2018-11-20 12:27:33.002] [info] Starting BLE scan
"errcode": "NRF_ERROR_BUSY",
"errmsg": "Error occured when starting scan. Errorcode: NRF_ERROR_BUSY (0x11)\n"
[2018-11-20 12:27:39.032] [info] COMM_BLE: Starting BLE scan
"errcode": "NRF_ERROR_BUSY",
"errmsg": "Error occured when starting scan. Errorcode: NRF_ERROR_BUSY (0x11)\n"
[2018-11-20 12:27:45.062] [info] COMM_BLE: Starting BLE scan
"errcode": "NRF_ERROR_BUSY",
"errmsg": "Error occured when starting scan. Errorcode: NRF_ERROR_BUSY (0x11)\n"
[2018-11-20 12:27:51.082] [info] COMM_BLE: Starting BLE scan
"errcode": "NRF_ERROR_BUSY",
"errmsg": "Error occured when starting scan. Errorcode: NRF_ERROR_BUSY (0x11)\n"
[2018-11-20 12:27:57.102] [info] COMM_BLE: Starting BLE scan
"errcode": "NRF_ERROR_BUSY",
"errmsg": "Error occured when starting scan. Errorcode: NRF_ERROR_BUSY (0x11)\n"

regards,
-Prashant.

[tesc]

Hi,

I could not find any known occurrences of this, and I am not convinced it is due to the scan not timing out. It may for instance be that the connectivity device has entered a bad state, somehow, or that there has been an USB error of some description.

Does it fail at around the same time each time, or is it some times down towards ten minutes before it breaks and other times up towards twenty minutes or more?

Does indeed handling the NRF_ERROR_BUSY error code by doing a scan stop followed by a retry solve the issue?

Regards,
Terje

[Prashant Ambardekar]

Thanks for looking into this.

It does not fail at the same time each time. In this state scan stop also fails. I added an event listener for scanTimedOut and here are new logs

[2018-11-21 11:43:28.046] [info] Starting BLE scan
[2018-11-21 11:43:31.115] [info] ###NRF_Log: 1: GAP_EVT_TIMEOUT time:2018-11-21T06:13:31.116Z connHandle:65535 src:2 srcName:bleGapTimeoutSrcScan << This is from logMessage event
[2018-11-21 11:43:31.119] [info] #### Scan timed out << This is from scanTimedOut event listener
[2018-11-21 11:43:34.275] [info] Starting BLE scan
[2018-11-21 11:43:37.525] [info] ###NRF_Log: 1: GAP_EVT_TIMEOUT time:2018-11-21T06:13:37.527Z connHandle:65535 src:2 srcName:bleGapTimeoutSrcScan
[2018-11-21 11:43:37.525] [info] #### Scan timed out
[2018-11-21 11:43:40.506] [info] Starting BLE scan
[2018-11-21 11:43:43.745] [info] ###NRF_Log: 1: GAP_EVT_TIMEOUT time:2018-11-21T06:13:43.747Z connHandle:65535 src:2 srcName:bleGapTimeoutSrcScan
[2018-11-21 11:43:43.745] [info] #### Scan timed out
[2018-11-21 11:43:46.725] [info] Starting BLE scan
[2018-11-21 11:43:49.795] [info] ###NRF_Log: 1: GAP_EVT_TIMEOUT time:2018-11-21T06:13:49.797Z connHandle:65535 src:2 srcName:bleGapTimeoutSrcScan
[2018-11-21 11:43:49.795] [info] #### Scan timed out
[2018-11-21 11:43:52.995] [info] Starting BLE scan
[2018-11-21 11:43:56.025] [info] ###NRF_Log: 1: GAP_EVT_TIMEOUT time:2018-11-21T06:13:56.027Z connHandle:65535 src:2 srcName:bleGapTimeoutSrcScan
[2018-11-21 11:43:56.025] [info] #### Scan timed out
[2018-11-21 11:43:59.226] [info] Starting BLE scan
[2018-11-21 11:44:02.307] [info] ###NRF_Log: 1: GAP_EVT_TIMEOUT time:2018-11-21T06:14:02.307Z connHandle:65535 src:2 srcName:bleGapTimeoutSrcScan
[2018-11-21 11:44:02.307] [info] #### Scan timed out
[2018-11-21 11:44:05.466] [info] Starting BLE scan

#### No time out event for above scan. All subsequent start scans fail

[2018-11-21 11:44:11.686] [info] Starting BLE scan
[2018-11-21 11:45:26.496] [error] Adapter error: {
"message": "Error occured when starting scan",
"description": {
"errno": 17,
"errcode": "NRF_ERROR_BUSY",
"erroperation": "starting scan",
"errmsg": "Error occured when starting scan. Errorcode: NRF_ERROR_BUSY (0x11)\n"
}

In this state, stop scan also fails with error

[2018-11-21 11:45:29.696] [info] COMM_BLE: Stopping BLE scan
[2018-11-21 11:45:29.736] [error] Adapter error: {
"message": "Error occured when stopping scanning",
"description": {
"errno": 8,
"errcode": "NRF_ERROR_INVALID_STATE",
"erroperation": "stopping scan",
"errmsg": "Error occured when stopping scan. Errorcode: NRF_ERROR_INVALID_STATE (0x8)\n"
}
}

Looks like the adapter has gone into a state where

- Start scan fails with NRF_ERROR_BUSY

- Stop scan fails with NRF_ERROR_INVALID_STATE

Please note that my stop scan is guarded by if(adapter.scanning == true). This evaluates to true in this state but stop scan still fails.

regards,

-Prashant.

[Prashant Ambardekar]

We have seen this issue on another 32 bit Windows 10 machine.