[TW#16442] BLE gatt server for muti-connect, disconnects and reconnects if using Android background connection mode

espressif / esp-idf

Espressif IoT Development Framework. Official development framework for Espressif SoCs.

Apache License 2.0

13.72k stars 7.3k forks source link

[TW#16442] BLE gatt server for muti-connect, disconnects and reconnects if using Android background connection mode #1263

Closed ayavilevich closed 6 years ago

ayavilevich commented 7 years ago

Hi,

I am writing a multi connect server, one that can accept several client connections at the same time. The idea is "gattc_multi_connect" but for server. Unfortunately, I am having disconnections. I boiled it down to a minimal case where I take a "gatt_server" example and add esp_ble_gap_start_advertising(&adv_params); in the end of the connect event to keep accepting connections. However, once I use this call I get disconnects with the first connection, without requiring to make any additional connections besides the first one. I have tested this happens for LG G4 with Android 6 and LG G5 with Android 7. I am using latest esp-idf.

This is very reproducible if I connect in "background mode". Where autoConnect=true for connectGatt method. https://developer.android.com/reference/android/bluetooth/BluetoothDevice.html#connectGatt(android.content.Context,%20boolean,%20android.bluetooth.BluetoothGattCallback) I have seen this less often, but it did also happen for regular connect modes.

Any idea what may be wrong? Can you try to reproduce? I can send my projects in a private channel if it will help. Any suggestions for troubleshooting/debug?

Console output for LG G4. One connect generates these connects and disconnects:

ets Jun  8 2016 00:22:57

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
ets Jun  8 2016 00:22:57

rst:0x10 (RTCWDT_RTC_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:2
load:0x3fff0018,len:4
load:0x3fff001c,len:5772
load:0x40078000,len:0
load:0x40078000,len:13804
entry 0x40079030
I (69) boot: Detected ESP32
I (32) boot: ESP-IDF v3.0-dev-1147-g8e04b861 2nd stage bootloader
I (32) boot: compile time 13:51:52
I (32) boot: Enabling RNG early entropy source...
I (38) boot: SPI Speed      : 40MHz
I (42) boot: SPI Mode       : DIO
I (46) boot: SPI Flash Size : 4MB
I (50) boot: Partition Table:
I (54) boot: ## Label            Usage          Type ST Offset   Length
I (61) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (69) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (76) boot:  2 factory          factory app      00 00 00010000 00100000
I (84) boot: End of partition table
I (88) esp_image: segment 0: paddr=0x00010020 vaddr=0x3f400020 size=0x2b4d0 (177360) map
I (158) esp_image: segment 1: paddr=0x0003b4f8 vaddr=0x3ffc0000 size=0x02b44 ( 11076) load
I (163) esp_image: segment 2: paddr=0x0003e044 vaddr=0x40080000 size=0x00400 (  1024) load
0x40080000: _iram_start at C:/prog/esp32/msys32/home/arik/esp/esp-idf/components/freertos/xtensa_vectors.S:1685

I (165) esp_image: segment 3: paddr=0x0003e44c vaddr=0x40080400 size=0x01bc4 (  7108) load
I (177) esp_image: segment 4: paddr=0x00040018 vaddr=0x400d0018 size=0x68aa0 (428704) map
0x400d0018: _stext at ??:?

I (332) esp_image: segment 5: paddr=0x000a8ac0 vaddr=0x40081fc4 size=0x107e4 ( 67556) load
0x40081fc4: _xt_user_exc at C:/prog/esp32/msys32/home/arik/esp/esp-idf/components/freertos/xtensa_vectors.S:652

I (360) esp_image: segment 6: paddr=0x000b92ac vaddr=0x400c0000 size=0x00000 (     0) load
I (371) boot: Loaded app from partition at offset 0x10000
I (371) boot: Disabling RNG early entropy source...
I (371) cpu_start: Pro cpu up.
I (375) cpu_start: Starting app cpu, entry point is 0x40080eec
0x40080eec: call_start_cpu1 at C:/prog/esp32/msys32/home/arik/esp/esp-idf/components/esp32/cpu_start.c:222

I (0) cpu_start: App cpu up.
I (386) heap_init: Initializing. RAM available for dynamic allocation:
I (392) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
I (398) heap_init: At 3FFCA9F8 len 00015608 (85 KiB): DRAM
I (404) heap_init: At 3FFE0440 len 00003BC0 (14 KiB): D/IRAM
I (411) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (417) heap_init: At 400927A8 len 0000D858 (54 KiB): IRAM
I (423) cpu_start: Pro cpu start user code
I (106) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (147) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (407) phy: phy_version: 366.0, ba9923d, Oct 31 2017, 18:06:17, 0, 0
I (437) GATTS_DEMO: REGISTER_APP_EVT, status 0, app_id 0

I (437) GATTS_DEMO: CREATE_SERVICE_EVT, status 0,  service_handle 40

I (447) GATTS_DEMO: SERVICE_START_EVT, status 0, service_handle 40

I (447) GATTS_DEMO: ADD_CHAR_EVT, status 0,  attr_handle 42, service_handle 40

I (457) GATTS_DEMO: the gatts demo char length = 3

I (457) GATTS_DEMO: prf_char[0] =11

I (467) GATTS_DEMO: prf_char[1] =22

I (467) GATTS_DEMO: prf_char[2] =33

I (477) GATTS_DEMO: ADD_DESCR_EVT, status 0, attr_handle 43, service_handle 40

I (487) GATTS_DEMO: REGISTER_APP_EVT, status 0, app_id 1

I (487) GATTS_DEMO: CREATE_SERVICE_EVT, status 0,  service_handle 44

I (497) GATTS_DEMO: SERVICE_START_EVT, status 0, service_handle 44

I (507) GATTS_DEMO: ADD_CHAR_EVT, status 0,  attr_handle 46, service_handle 44

I (507) GATTS_DEMO: ADD_DESCR_EVT, status 0, attr_handle 47, service_handle 44

I (4887) GATTS_DEMO: ESP_GATTS_CONNECT_EVT, conn_id 0, remote 49:35:d3:5b:1e:19:
I (4887) GATTS_DEMO: CONNECT_EVT, conn_id 0, remote 49:35:d3:5b:1e:19:
I (5517) GATTS_DEMO: update connetion params status = 0, min_int = 16, max_int = 32,conn_int = 6,latency = 0, timeout = 2000
I (45867) GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT
I (84397) GATTS_DEMO: ESP_GATTS_CONNECT_EVT, conn_id 0, remote 49:35:d3:5b:1e:19:
I (84397) GATTS_DEMO: CONNECT_EVT, conn_id 0, remote 49:35:d3:5b:1e:19:
I (85027) GATTS_DEMO: update connetion params status = 0, min_int = 16, max_int = 32,conn_int = 6,latency = 0, timeout = 2000
I (90697) GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT
I (94397) GATTS_DEMO: ESP_GATTS_CONNECT_EVT, conn_id 0, remote 49:35:d3:5b:1e:19:
I (94397) GATTS_DEMO: CONNECT_EVT, conn_id 0, remote 49:35:d3:5b:1e:19:
I (96407) GATTS_DEMO: update connetion params status = 16, min_int = 16, max_int = 32,conn_int = 39,latency = 0, timeout = 2000
I (112377) GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT
I (114347) GATTS_DEMO: ESP_GATTS_CONNECT_EVT, conn_id 0, remote 49:35:d3:5b:1e:19:
I (114347) GATTS_DEMO: CONNECT_EVT, conn_id 0, remote 49:35:d3:5b:1e:19:
I (116357) GATTS_DEMO: update connetion params status = 16, min_int = 16, max_int = 32,conn_int = 39,latency = 0, timeout = 2000
I (132347) GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT
I (134357) GATTS_DEMO: ESP_GATTS_CONNECT_EVT, conn_id 0, remote 49:35:d3:5b:1e:19:
I (134357) GATTS_DEMO: CONNECT_EVT, conn_id 0, remote 49:35:d3:5b:1e:19:
I (136367) GATTS_DEMO: update connetion params status = 16, min_int = 16, max_int = 32,conn_int = 39,latency = 0, timeout = 2000
I (158997) GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT
I (159387) GATTS_DEMO: ESP_GATTS_CONNECT_EVT, conn_id 0, remote 49:35:d3:5b:1e:19:
I (159387) GATTS_DEMO: CONNECT_EVT, conn_id 0, remote 49:35:d3:5b:1e:19:
I (161397) GATTS_DEMO: update connetion params status = 16, min_int = 16, max_int = 32,conn_int = 39,latency = 0, timeout = 2000
I (177347) GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT
[stop]

same for LG G5

ets Jun  8 2016 00:22:57

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
ets Jun  8 2016 00:22:57

rst:0x10 (RTCWDT_RTC_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:2
load:0x3fff0018,len:4
load:0x3fff001c,len:5772
load:0x40078000,len:0
load:0x40078000,len:13804
entry 0x40079030
I (69) boot: Detected ESP32
I (32) boot: ESP-IDF v3.0-dev-1147-g8e04b861 2nd stage bootloader
I (32) boot: compile time 13:51:52
I (32) boot: Enabling RNG early entropy source...
I (38) boot: SPI Speed      : 40MHz
I (42) boot: SPI Mode       : DIO
I (46) boot: SPI Flash Size : 4MB
I (50) boot: Partition Table:
I (54) boot: ## Label            Usage          Type ST Offset   Length
I (61) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (69) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (76) boot:  2 factory          factory app      00 00 00010000 00100000
I (84) boot: End of partition table
I (88) esp_image: segment 0: paddr=0x00010020 vaddr=0x3f400020 size=0x2b4d0 (177
360) map
I (158) esp_image: segment 1: paddr=0x0003b4f8 vaddr=0x3ffc0000 size=0x02b44 ( 1
1076) load
I (163) esp_image: segment 2: paddr=0x0003e044 vaddr=0x40080000 size=0x00400 (
1024) load
0x40080000: _iram_start at C:/prog/esp32/msys32/home/arik/esp/esp-idf/components
/freertos/xtensa_vectors.S:1685

I (165) esp_image: segment 3: paddr=0x0003e44c vaddr=0x40080400 size=0x01bc4 (
7108) load
I (177) esp_image: segment 4: paddr=0x00040018 vaddr=0x400d0018 size=0x68aa0 (42
8704) map
0x400d0018: _stext at ??:?

I (332) esp_image: segment 5: paddr=0x000a8ac0 vaddr=0x40081fc4 size=0x107e4 ( 6
7556) load
0x40081fc4: _xt_user_exc at C:/prog/esp32/msys32/home/arik/esp/esp-idf/component
s/freertos/xtensa_vectors.S:652

I (360) esp_image: segment 6: paddr=0x000b92ac vaddr=0x400c0000 size=0x00000 (
   0) load
I (371) boot: Loaded app from partition at offset 0x10000
I (371) boot: Disabling RNG early entropy source...
I (371) cpu_start: Pro cpu up.
I (375) cpu_start: Starting app cpu, entry point is 0x40080eec
0x40080eec: call_start_cpu1 at C:/prog/esp32/msys32/home/arik/esp/esp-idf/compon
ents/esp32/cpu_start.c:222

I (0) cpu_start: App cpu up.
I (386) heap_init: Initializing. RAM available for dynamic allocation:
I (392) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
I (398) heap_init: At 3FFCA9F8 len 00015608 (85 KiB): DRAM
I (404) heap_init: At 3FFE0440 len 00003BC0 (14 KiB): D/IRAM
I (411) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (417) heap_init: At 400927A8 len 0000D858 (54 KiB): IRAM
I (423) cpu_start: Pro cpu start user code
I (106) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (147) system_api: Base MAC address is not set, read default base MAC address f
rom BLK0 of EFUSE
I (417) phy: phy_version: 366.0, ba9923d, Oct 31 2017, 18:06:17, 0, 0
I (447) GATTS_DEMO: REGISTER_APP_EVT, status 0, app_id 0

I (447) GATTS_DEMO: CREATE_SERVICE_EVT, status 0,  service_handle 40

I (457) GATTS_DEMO: SERVICE_START_EVT, status 0, service_handle 40

I (457) GATTS_DEMO: ADD_CHAR_EVT, status 0,  attr_handle 42, service_handle 40

I (467) GATTS_DEMO: the gatts demo char length = 3

I (467) GATTS_DEMO: prf_char[0] =11

I (477) GATTS_DEMO: prf_char[1] =22

I (477) GATTS_DEMO: prf_char[2] =33

I (487) GATTS_DEMO: ADD_DESCR_EVT, status 0, attr_handle 43, service_handle 40

I (497) GATTS_DEMO: REGISTER_APP_EVT, status 0, app_id 1

I (497) GATTS_DEMO: CREATE_SERVICE_EVT, status 0,  service_handle 44

I (507) GATTS_DEMO: SERVICE_START_EVT, status 0, service_handle 44

I (517) GATTS_DEMO: ADD_CHAR_EVT, status 0,  attr_handle 46, service_handle 44

I (517) GATTS_DEMO: ADD_DESCR_EVT, status 0, attr_handle 47, service_handle 44

I (2277) GATTS_DEMO: ESP_GATTS_CONNECT_EVT, conn_id 0, remote 7d:80:7f:b1:08:16:
I (2277) GATTS_DEMO: CONNECT_EVT, conn_id 0, remote 7d:80:7f:b1:08:16:
I (2867) GATTS_DEMO: update connetion params status = 0, min_int = 16, max_int = 32,conn_int = 24,latency = 0, timeout = 400
I (11127) GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT
I (12227) GATTS_DEMO: ESP_GATTS_CONNECT_EVT, conn_id 0, remote 7d:80:7f:b1:08:16:
I (12227) GATTS_DEMO: CONNECT_EVT, conn_id 0, remote 7d:80:7f:b1:08:16:
I (12827) GATTS_DEMO: update connetion params status = 0, min_int = 16, max_int = 32,conn_int = 24,latency = 0, timeout = 400
I (21117) GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT
I (22227) GATTS_DEMO: ESP_GATTS_CONNECT_EVT, conn_id 0, remote 7d:80:7f:b1:08:16:
I (22227) GATTS_DEMO: CONNECT_EVT, conn_id 0, remote 7d:80:7f:b1:08:16:
I (22877) GATTS_DEMO: update connetion params status = 0, min_int = 16, max_int = 32,conn_int = 24,latency = 0, timeout = 400
I (31137) GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT
I (32227) GATTS_DEMO: ESP_GATTS_CONNECT_EVT, conn_id 0, remote 5a:ba:d9:ca:43:90:
I (32237) GATTS_DEMO: CONNECT_EVT, conn_id 0, remote 5a:ba:d9:ca:43:90:
I (32837) GATTS_DEMO: update connetion params status = 0, min_int = 16, max_int = 32,conn_int = 24,latency = 0, timeout = 400
I (38187) GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT
I (39447) GATTS_DEMO: ESP_GATTS_CONNECT_EVT, conn_id 0, remote 5a:ba:d9:ca:43:90:
I (39447) GATTS_DEMO: CONNECT_EVT, conn_id 0, remote 5a:ba:d9:ca:43:90:
I (39807) GATTS_DEMO: update connetion params status = 0, min_int = 16, max_int = 32,conn_int = 24,latency = 0, timeout = 400
I (44617) GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT
I (47277) GATTS_DEMO: ESP_GATTS_CONNECT_EVT, conn_id 0, remote 5a:ba:d9:ca:43:90:
I (47287) GATTS_DEMO: CONNECT_EVT, conn_id 0, remote 5a:ba:d9:ca:43:90:
I (47867) GATTS_DEMO: update connetion params status = 0, min_int = 16, max_int = 32,conn_int = 24,latency = 0, timeout = 400
I (52527) GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT
I (57217) GATTS_DEMO: ESP_GATTS_CONNECT_EVT, conn_id 0, remote 5a:ba:d9:ca:43:90:
I (57217) GATTS_DEMO: CONNECT_EVT, conn_id 0, remote 5a:ba:d9:ca:43:90:
I (57587) GATTS_DEMO: update connetion params status = 0, min_int = 16, max_int = 32,conn_int = 24,latency = 0, timeout = 400
I (66107) GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT
I (67237) GATTS_DEMO: ESP_GATTS_CONNECT_EVT, conn_id 0, remote 5a:ba:d9:ca:43:90:
I (67237) GATTS_DEMO: CONNECT_EVT, conn_id 0, remote 5a:ba:d9:ca:43:90:
I (67627) GATTS_DEMO: update connetion params status = 0, min_int = 16, max_int = 32,conn_int = 24,latency = 0, timeout = 400
I (76127) GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT
I (76577) GATTS_DEMO: ESP_GATTS_CONNECT_EVT, conn_id 0, remote 5a:ba:d9:ca:43:90:
I (76577) GATTS_DEMO: CONNECT_EVT, conn_id 0, remote 5a:ba:d9:ca:43:90:
I (77177) GATTS_DEMO: update connetion params status = 0, min_int = 16, max_int = 32,conn_int = 24,latency = 0, timeout = 400
I (81747) GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT
I (82997) GATTS_DEMO: ESP_GATTS_CONNECT_EVT, conn_id 0, remote 5a:ba:d9:ca:43:90:
I (82997) GATTS_DEMO: CONNECT_EVT, conn_id 0, remote 5a:ba:d9:ca:43:90:
I (83597) GATTS_DEMO: update connetion params status = 0, min_int = 16, max_int = 32,conn_int = 24,latency = 0, timeout = 400
I (94497) GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT
I (94657) GATTS_DEMO: ESP_GATTS_CONNECT_EVT, conn_id 0, remote 5a:ba:d9:ca:43:90:
I (94657) GATTS_DEMO: CONNECT_EVT, conn_id 0, remote 5a:ba:d9:ca:43:90:
I (95237) GATTS_DEMO: update connetion params status = 0, min_int = 16, max_int = 32,conn_int = 24,latency = 0, timeout = 400
I (100917) GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT
I (103427) GATTS_DEMO: ESP_GATTS_CONNECT_EVT, conn_id 0, remote 5a:ba:d9:ca:43:90:
I (103427) GATTS_DEMO: CONNECT_EVT, conn_id 0, remote 5a:ba:d9:ca:43:90:
I (103967) GATTS_DEMO: update connetion params status = 0, min_int = 16, max_int = 32,conn_int = 24,latency = 0, timeout = 400
I (109857) GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT
I (112427) GATTS_DEMO: ESP_GATTS_CONNECT_EVT, conn_id 0, remote 5a:ba:d9:ca:43:90:
I (112427) GATTS_DEMO: CONNECT_EVT, conn_id 0, remote 5a:ba:d9:ca:43:90:
I (113027) GATTS_DEMO: update connetion params status = 0, min_int = 16, max_int = 32,conn_int = 24,latency = 0, timeout = 400
I (117567) GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT
I (118827) GATTS_DEMO: ESP_GATTS_CONNECT_EVT, conn_id 0, remote 5a:ba:d9:ca:43:90:
I (118827) GATTS_DEMO: CONNECT_EVT, conn_id 0, remote 5a:ba:d9:ca:43:90:
I (119417) GATTS_DEMO: update connetion params status = 0, min_int = 16, max_int = 32,conn_int = 24,latency = 0, timeout = 400
I (125217) GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT
I (125337) GATTS_DEMO: ESP_GATTS_CONNECT_EVT, conn_id 0, remote 5a:ba:d9:ca:43:90:
I (125337) GATTS_DEMO: CONNECT_EVT, conn_id 0, remote 5a:ba:d9:ca:43:90:
I (125927) GATTS_DEMO: update connetion params status = 0, min_int = 16, max_int = 32,conn_int = 24,latency = 0, timeout = 400
I (131637) GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT
I (132867) GATTS_DEMO: ESP_GATTS_CONNECT_EVT, conn_id 0, remote 5a:ba:d9:ca:43:90:
I (132867) GATTS_DEMO: CONNECT_EVT, conn_id 0, remote 5a:ba:d9:ca:43:90:
I (133457) GATTS_DEMO: update connetion params status = 0, min_int = 16, max_int = 32,conn_int = 24,latency = 0, timeout = 400
I (138057) GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT
I (138187) GATTS_DEMO: ESP_GATTS_CONNECT_EVT, conn_id 0, remote 5a:ba:d9:ca:43:90:
I (138187) GATTS_DEMO: CONNECT_EVT, conn_id 0, remote 5a:ba:d9:ca:43:90:
I (138797) GATTS_DEMO: update connetion params status = 0, min_int = 16, max_int = 32,conn_int = 24,latency = 0, timeout = 400
I (143157) GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT
I (144497) GATTS_DEMO: ESP_GATTS_CONNECT_EVT, conn_id 0, remote 5a:ba:d9:ca:43:90:
I (144497) GATTS_DEMO: CONNECT_EVT, conn_id 0, remote 5a:ba:d9:ca:43:90:
I (145097) GATTS_DEMO: update connetion params status = 0, min_int = 16, max_int = 32,conn_int = 24,latency = 0, timeout = 400
I (149547) GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT
I (150807) GATTS_DEMO: ESP_GATTS_CONNECT_EVT, conn_id 0, remote 5a:ba:d9:ca:43:90:
I (150807) GATTS_DEMO: CONNECT_EVT, conn_id 0, remote 5a:ba:d9:ca:43:90:
[stop]

ayavilevich commented 6 years ago

Reproduction instructions:

Implement multi-connect server by calling esp_ble_gap_start_advertising in a "connect" event. I based the test on "gatt_server" example. This will keep advertising, but we shouldn't actually connect a second time as more changes needed to do that. Using an Android 6.0 phone (I used LG G4), connect to the ESP32 in "background mode" where autoConnect=true is passed in connectGatt. This mode registers the ESP32 MAC in a whitelist on the BT controller in the phone. I can provide Android project code if needed. Next, initiate a "background connect" to another MAC address, this can be a random one and doesn't have to belong to a running device. The ESP32 will start disconnecting and reconnecting now. this will be an issue until BT is restarted by turning it off then on in the Android phone.

ayavilevich commented 6 years ago

Can someone provide an update or response? Is this issue confirmed? Are we waiting for a fix to be made?

I would appreciate if people can try to reproduce with different Android/iOS phones and report results.

Here are most up to date reproduce instructions:

Take (latest) ESP_IDF.
copy gatt_server sample and add a call to esp_ble_gap_start_advertising(&adv_params); in the end of the ESP_GATTS_CONNECT_EVT event in profile A. This is to re-enable advertising and allow multi-connect. Make and flash.
Take an Android phone with "nRF Connect" app. Optionally enable logging.
Scan for devices and "Connect with autoConnect" to the device (this is in the extended CONNECT menu).
See if the connection stays connected or enters a disconnect/reconnect state.

I can also provide SmartRF capture if it is needed. This stays connected well on older Android phones but it is not working on newer LG G4 and G5. Additionally, it takes relatively long time to connect. About 10sec.

Here is console output

I (557) GATTS_DEMO: ADD_DESCR_EVT, status 0, attr_handle 47, service_handle 44

I (11707) GATTS_DEMO: ESP_GATTS_CONNECT_EVT, conn_id 0, remote 46:a8:ea:6b:da:85:
I (11707) GATTS_DEMO: CONNECT_EVT, conn_id 0, remote 46:a8:ea:6b:da:85:
I (12307) GATTS_DEMO: update connetion params status = 0, min_int = 16, max_int = 32,conn_int = 24,latency = 0, timeout = 400
I (12587) GATTS_DEMO: update connetion params status = 0, min_int = 0, max_int = 0,conn_int = 6,latency = 0, timeout = 2000
I (12937) GATTS_DEMO: update connetion params status = 0, min_int = 0, max_int = 0,conn_int = 24,latency = 0, timeout = 400
I (20687) GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT
I (21737) GATTS_DEMO: ESP_GATTS_CONNECT_EVT, conn_id 0, remote 46:a8:ea:6b:da:85:
I (21737) GATTS_DEMO: CONNECT_EVT, conn_id 0, remote 46:a8:ea:6b:da:85:
I (22327) GATTS_DEMO: update connetion params status = 0, min_int = 16, max_int = 32,conn_int = 24,latency = 0, timeout = 400
I (30617) GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT
I (31717) GATTS_DEMO: ESP_GATTS_CONNECT_EVT, conn_id 0, remote 46:a8:ea:6b:da:85:
I (31727) GATTS_DEMO: CONNECT_EVT, conn_id 0, remote 46:a8:ea:6b:da:85:
I (31917) GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT
I (36737) GATTS_DEMO: ESP_GATTS_CONNECT_EVT, conn_id 0, remote 46:a8:ea:6b:da:85:
I (36737) GATTS_DEMO: CONNECT_EVT, conn_id 0, remote 46:a8:ea:6b:da:85:
I (37327) GATTS_DEMO: update connetion params status = 0, min_int = 16, max_int = 32,conn_int = 24,llatency = 0, timeout = 400
I (45647) GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT
I (46747) GATTS_DEMO: ESP_GATTS_CONNECT_EVT, conn_id 0, remote 46:a8:ea:6b:da:85:
I (46747) GATTS_DEMO: CONNECT_EVT, conn_id 0, remote 46:a8:ea:6b:dda:85:
I (46987) GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT
I (51757) GATTS_DEMO: ESP_GATTS_CONNECT_EVT, conn_id 0, remote 46:a8:ea:6b:da:85:
I (51757) GATTS_DEMO: CONNECT_EVT, conn_id 0, remote 46:a8:ea:6b:daa:85:
I (52347) GATTS_DEMO: update connetion params status = 0, min_int = 16, max_int = 32,conn_int = 24,latency = 0, timeout = 400
I (53877) GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT

Here is nRF log

nRF Connect, 2018-02-11
ESP_GATTS_DEMO (30:AE:A4:05:01:DA)
V14:54:49.128Connecting to 30:AE:A4:05:01:DA...
D14:54:49.128gatt = device.connectGatt(autoConnect = true, TRANSPORT_LE)
D14:54:49.566[Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I14:54:49.566Connected to 30:AE:A4:05:01:DA
D14:54:49.573wait(1600ms)
D14:54:49.584[Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
V14:54:51.176Discovering services...
D14:54:51.176gatt.discoverServices()
D14:54:51.182[Callback] Services discovered with status: 0
I14:54:51.188Services discovered
V14:54:51.209Generic Attribute (0x1801)
- Service Changed [I] (0x2A05)
Generic Access (0x1800)
- Device Name [R] (0x2A00)
- Appearance [R] (0x2A01)
- Central Address Resolution [R] (0x2AA6)
Unknown Service (000000ff-0000-1000-8000-00805f9b34fb)
- Unknown Characteristic [N R W] (0000ff01-0000-1000-8000-00805f9b34fb)
   Client Characteristic Configuration (0x2902)
Unknown Service (000000ee-0000-1000-8000-00805f9b34fb)
- Unknown Characteristic [N R W] (0000ee01-0000-1000-8000-00805f9b34fb)
   Client Characteristic Configuration (0x2902)
D14:54:54.458[Callback] Connection state changed with status: 8 and new state: DISCONNECTED (0)
E14:54:54.459Error 8 (0x8): GATT CONN TIMEOUT
I14:54:54.459Disconnected
D14:54:54.557[Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
D14:54:59.572[Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
D14:54:59.573gatt.close()
D14:54:59.586wait(200)
V14:54:59.787Connecting to 30:AE:A4:05:01:DA...
D14:54:59.788gatt = device.connectGatt(autoConnect = true, TRANSPORT_LE)
D14:54:59.790[Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
D14:54:59.790[Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
I14:54:59.791Disconnected
D14:55:04.569[Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I14:55:04.569Connected to 30:AE:A4:05:01:DA
D14:55:04.571[Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
D14:55:04.576wait(1600ms)
V14:55:05.458Disconnecting...
D14:55:05.458gatt.disconnect()
D14:55:05.473[Callback] Connection state changed with status: 0 and new state: DISCONNECTED (0)
I14:55:05.473Disconnected
D14:55:05.475gatt.refresh() (hidden)
D14:55:05.560[Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
D14:55:07.893gatt.close()
D14:55:07.896wait(200)

Weijian-Espressif commented 6 years ago

sorry for late, please update to the latest IDF and try.

ayavilevich commented 6 years ago

Hi @Weijian-Espressif ,

Tested with latest IDF. Still seeing the same behavior using the reproduction instructions above. Can you reproduce on your end? Here are logs:

--- idf_monitor on COM15 115200 ---
--- Quit: Ctrl+] | Menu: Ctrl+T | Help: Ctrl+T followed by Ctrl+H ---
ets Jun  8 2016 00:22:57

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:2
load:0x3fff0018,len:4
load:0x3fff001c,len:5704
load:0x40078000,len:0
ho 12 tail 0 room 4
load:0x40078000,len:13912
entry 0x40078fd8
I (29) boot: ESP-IDF v3.1-dev-463-g77eae33a 2nd stage bootloader
I (29) boot: compile time 21:09:00
I (30) boot: Enabling RNG early entropy source...
I (35) boot: SPI Speed      : 40MHz
I (39) boot: SPI Mode       : DIO
I (43) boot: SPI Flash Size : 4MB
I (47) boot: Partition Table:
I (51) boot: ## Label            Usage          Type ST Offset   Length
I (58) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (66) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (73) boot:  2 factory          factory app      00 00 00010000 00100000
I (81) boot: End of partition table
I (85) esp_image: segment 0: paddr=0x00010020 vaddr=0x3f400020 size=0x2b8f0 (178
416) map
I (156) esp_image: segment 1: paddr=0x0003b918 vaddr=0x3ffc0000 size=0x02b84 ( 1
1140) load
I (160) esp_image: segment 2: paddr=0x0003e4a4 vaddr=0x40080000 size=0x00400 (
1024) load
0x40080000: _iram_start at C:/prog/esp32/msys32/home/arik/esp/esp-idf/components
/freertos/xtensa_vectors.S:1685

I (163) esp_image: segment 3: paddr=0x0003e8ac vaddr=0x40080400 size=0x01764 (
5988) load
I (174) esp_image: segment 4: paddr=0x00040018 vaddr=0x400d0018 size=0x71214 (46
3380) map
0x400d0018: _stext at ??:?

I (341) esp_image: segment 5: paddr=0x000b1234 vaddr=0x40081b64 size=0x0bedc ( 4
8860) load
0x40081b64: timer_overflow_happened at C:/prog/esp32/msys32/home/arik/esp/esp-id
f/components/esp32/esp_timer_esp32.c:144
 (inlined by) timer_alarm_isr at C:/prog/esp32/msys32/home/arik/esp/esp-idf/comp
onents/esp32/esp_timer_esp32.c:248

I (362) esp_image: segment 6: paddr=0x000bd118 vaddr=0x400c0000 size=0x00000 (     0) load
I (370) boot: Loaded app from partition at offset 0x10000
I (370) boot: Disabling RNG early entropy source...
I (371) cpu_start: Pro cpu up.
I (375) cpu_start: Starting app cpu, entry point is 0x40080f30
0x40080f30: call_start_cpu1 at C:/prog/esp32/msys32/home/arik/esp/esp-idf/components/esp32/cpu_start.c:225

I (0) cpu_start: App cpu up.
I (385) heap_init: Initializing. RAM available for dynamic allocation:
I (392) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
I (398) heap_init: At 3FFCABE0 len 00015420 (85 KiB): DRAM
I (404) heap_init: At 3FFE0440 len 00003BC0 (14 KiB): D/IRAM
I (411) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (417) heap_init: At 4008DA40 len 000125C0 (73 KiB): IRAM
I (423) cpu_start: Pro cpu start user code
I (106) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (196) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (506) phy: phy_version: 383.0, 79a622c, Jan 30 2018, 15:38:06, 0, 0
I (536) GATTS_DEMO: REGISTER_APP_EVT, status 0, app_id 0

I (536) GATTS_DEMO: CREATE_SERVICE_EVT, status 0,  service_handle 40

I (536) GATTS_DEMO: SERVICE_START_EVT, status 0, service_handle 40

I (546) GATTS_DEMO: ADD_CHAR_EVT, status 0,  attr_handle 42, service_handle 40

I (546) GATTS_DEMO: the gatts demo char length = 3

I (556) GATTS_DEMO: prf_char[0] =11

I (556) GATTS_DEMO: prf_char[1] =22

I (566) GATTS_DEMO: prf_char[2] =33

I (566) GATTS_DEMO: ADD_DESCR_EVT, status 0, attr_handle 43, service_handle 40

I (576) GATTS_DEMO: REGISTER_APP_EVT, status 0, app_id 1

I (586) GATTS_DEMO: CREATE_SERVICE_EVT, status 0,  service_handle 44

I (586) GATTS_DEMO: SERVICE_START_EVT, status 0, service_handle 44

I (596) GATTS_DEMO: ADD_CHAR_EVT, status 0,  attr_handle 46, service_handle 44

I (606) GATTS_DEMO: ADD_DESCR_EVT, status 0, attr_handle 47, service_handle 44

I (1063956) GATTS_DEMO: ESP_GATTS_CONNECT_EVT, conn_id 0, remote 61:3b:e0:fb:9b:07:
I (1063956) GATTS_DEMO: CONNECT_EVT, conn_id 0, remote 61:3b:e0:fb:9b:07:
I (1065966) GATTS_DEMO: update connetion params status = 16, min_int = 16, max_int = 32,conn_int = 39,latenc
y = 0, timeout = 2000
I (1077276) GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT
I (1077586) GATTS_DEMO: ESP_GATTS_CONNECT_EVT, conn_id 0, remote 61:3b:e0:fb:9b:07:
I (1077586) GATTS_DEMO: CONNECT_EVT, conn_id 0, remote 61:3b:e0:fb:9b:07:
I (1078276) GATTS_DEMO: update connetion params status = 0, min_int = 16, max_int = 32,conn_int = 6,latency
= 0, timeout = 2000
I (1084196) GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT
I (1087576) GATTS_DEMO: ESP_GATTS_CONNECT_EVT, conn_id 0, remote 61:3b:e0:fb:9b:07:
I (1087576) GATTS_DEMO: CONNECT_EVT, conn_id 0, remote 61:3b:e0:fb:9b:07:
I (1089586) GATTS_DEMO: update connetion params status = 16, min_int = 16, max_int = 32,conn_int = 39,latenc
y = 0, timeout = 2000
I (1105756) GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT
I (1107616) GATTS_DEMO: ESP_GATTS_CONNECT_EVT, conn_id 0, remote 61:3b:e0:fb:9b:07:
I (1107616) GATTS_DEMO: CONNECT_EVT, conn_id 0, remote 61:3b:e0:fb:9b:07:
I (1109616) GATTS_DEMO: update connetion params status = 16, min_int = 16, max_int = 32,conn_int = 39,latenc
y = 0, timeout = 2000
I (1111706) GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT
I (1117556) GATTS_DEMO: ESP_GATTS_CONNECT_EVT, conn_id 0, remote 61:3b:e0:fb:9b:07:
I (1117566) GATTS_DEMO: CONNECT_EVT, conn_id 0, remote 61:3b:e0:fb:9b:07:
I (1118296) GATTS_DEMO: update connetion params status = 0, min_int = 16, max_int = 32,conn_int = 6,latency
= 0, timeout = 2000
I (1135686) GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT

nRF log

nRF Connect, 2018-03-14
ESP_GATTS_DEMO (30:AE:A4:36:82:3A)
V21:41:16.054Connecting to 30:AE:A4:36:82:3A...
D21:41:16.054gatt = device.connectGatt(autoConnect = true, TRANSPORT_LE)
D21:41:18.705[Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I21:41:18.705Connected to 30:AE:A4:36:82:3A
D21:41:18.707[Callback] Connection state changed with status: 8 and new state: DISCONNECTED (0)
E21:41:18.707Error 8 (0x8): GATT CONN TIMEOUT
I21:41:18.707Disconnected
D21:41:18.749[Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
D21:41:18.749gatt.close()
D21:41:18.751wait(200)
V21:41:18.954Connecting to 30:AE:A4:36:82:3A...
D21:41:18.954gatt = device.connectGatt(autoConnect = true, TRANSPORT_LE)
D21:41:18.973[Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
I21:41:18.989Disconnected
D21:41:19.265[Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I21:41:19.265Connected to 30:AE:A4:36:82:3A
V21:41:19.291Discovering services...
D21:41:19.291gatt.discoverServices()
D21:41:19.317[Callback] Connection state changed with status: 62 and new state: DISCONNECTED (0)
E21:41:19.317Error 62 (0x3e): GATT CONN FAIL ESTABLISH
I21:41:19.317Disconnected
D21:41:19.678[Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
D21:41:19.679gatt.close()
D21:41:19.687wait(200)
V21:41:19.889Connecting to 30:AE:A4:36:82:3A...
D21:41:19.889gatt = device.connectGatt(autoConnect = true, TRANSPORT_LE)
D21:41:19.894[Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
I21:41:19.895Disconnected
D21:41:20.220[Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I21:41:20.220Connected to 30:AE:A4:36:82:3A
D21:41:20.224[Callback] Connection state changed with status: 8 and new state: DISCONNECTED (0)
E21:41:20.224Error 8 (0x8): GATT CONN TIMEOUT
I21:41:20.224Disconnected
D21:41:20.241[Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
D21:41:20.241gatt.close()
D21:41:20.243wait(200)
V21:41:20.448Connecting to 30:AE:A4:36:82:3A...
D21:41:20.448gatt = device.connectGatt(autoConnect = true, TRANSPORT_LE)
D21:41:20.459[Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
I21:41:20.493Disconnected
D21:41:21.666[Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I21:41:21.666Connected to 30:AE:A4:36:82:3A
D21:41:21.671[Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
V21:41:21.693Discovering services...
D21:41:21.693gatt.discoverServices()
D21:41:21.694[Callback] Connection state changed with status: 8 and new state: DISCONNECTED (0)
E21:41:21.694Error 8 (0x8): GATT CONN TIMEOUT
I21:41:21.694Disconnected
D21:41:21.711[Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
D21:41:32.360[Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I21:41:32.360Connected to 30:AE:A4:36:82:3A
D21:41:32.398[Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
V21:41:32.398Discovering services...
D21:41:32.398gatt.discoverServices()
D21:41:33.300[Callback] Services discovered with status: 0
I21:41:33.303Services discovered
V21:41:33.328Generic Attribute (0x1801)
- Service Changed [I] (0x2A05)
Generic Access (0x1800)
- Device Name [R] (0x2A00)
- Appearance [R] (0x2A01)
- Central Address Resolution [R] (0x2AA6)
Unknown Service (000000ff-0000-1000-8000-00805f9b34fb)
- Unknown Characteristic [N R W] (0000ff01-0000-1000-8000-00805f9b34fb)
   Client Characteristic Configuration (0x2902)
Unknown Service (000000ee-0000-1000-8000-00805f9b34fb)
- Unknown Characteristic [N R W] (0000ee01-0000-1000-8000-00805f9b34fb)
   Client Characteristic Configuration (0x2902)
D21:41:37.821[Callback] Connection state changed with status: 8 and new state: DISCONNECTED (0)
E21:41:37.821Error 8 (0x8): GATT CONN TIMEOUT
I21:41:37.821Disconnected
D21:41:37.903[Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
D21:41:42.948[Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I21:41:42.948Connected to 30:AE:A4:36:82:3A
D21:41:42.952[Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
V21:41:42.989Discovering services...
D21:41:42.989gatt.discoverServices()
D21:41:42.999[Callback] Services discovered with status: 0
I21:41:43.001Services discovered
V21:41:43.027Generic Attribute (0x1801)
- Service Changed [I] (0x2A05)
Generic Access (0x1800)
- Device Name [R] (0x2A00)
- Appearance [R] (0x2A01)
- Central Address Resolution [R] (0x2AA6)
Unknown Service (000000ff-0000-1000-8000-00805f9b34fb)
- Unknown Characteristic [N R W] (0000ff01-0000-1000-8000-00805f9b34fb)
   Client Characteristic Configuration (0x2902)
Unknown Service (000000ee-0000-1000-8000-00805f9b34fb)
- Unknown Characteristic [N R W] (0000ee01-0000-1000-8000-00805f9b34fb)
   Client Characteristic Configuration (0x2902)
D21:41:47.756[Callback] Connection state changed with status: 8 and new state: DISCONNECTED (0)
E21:41:47.756Error 8 (0x8): GATT CONN TIMEOUT
I21:41:47.756Disconnected
D21:41:47.838[Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
D21:42:02.985[Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
D21:42:02.985gatt.close()
D21:42:02.989wait(200)
V21:42:03.192Connecting to 30:AE:A4:36:82:3A...
D21:42:03.192gatt = device.connectGatt(autoConnect = true, TRANSPORT_LE)
D21:42:03.204[Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I21:42:03.204Connected to 30:AE:A4:36:82:3A
V21:42:03.226Discovering services...
D21:42:03.226gatt.discoverServices()
D21:42:03.236[Callback] Services discovered with status: 0
I21:42:03.239Services discovered
V21:42:03.261Generic Attribute (0x1801)
- Service Changed [I] (0x2A05)
Generic Access (0x1800)
- Device Name [R] (0x2A00)
- Appearance [R] (0x2A01)
- Central Address Resolution [R] (0x2AA6)
Unknown Service (000000ff-0000-1000-8000-00805f9b34fb)
- Unknown Characteristic [N R W] (0000ff01-0000-1000-8000-00805f9b34fb)
   Client Characteristic Configuration (0x2902)
Unknown Service (000000ee-0000-1000-8000-00805f9b34fb)
- Unknown Characteristic [N R W] (0000ee01-0000-1000-8000-00805f9b34fb)
   Client Characteristic Configuration (0x2902)
V21:42:06.948Disconnecting...
D21:42:06.948gatt.disconnect()
D21:42:06.970[Callback] Connection state changed with status: 0 and new state: DISCONNECTED (0)
I21:42:06.970Disconnected
D21:42:06.971gatt.refresh() (hidden)
D21:42:06.978gatt.close()
D21:42:06.981wait(200)
D21:42:07.042[Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED

EspressifApp commented 6 years ago

sorry for being late . 1. please printf the reason of ESP_GATTS_DISCONNECT_EVT.

lightblue APP or nrf connect APP work well with gatt server ?

ayavilevich commented 6 years ago

@EspressifApp

1 The common reason at first is 8 (ESP_GATT_CONN_TIMEOUT) but after some back and forth I was able to get 19 and 31 too. Interestingly 31 (0x1F) is not in the enum.

2 I am doing my tests with nRF Connect. To reproduce you need two things: Use "Connect with autoConnect" to connect the device (this is in the extended CONNECT menu). Add a call to esp_ble_gap_start_advertising(&adv_params); in the ~~ESP_GATTS_DISCONNECT_EVT~~ ESP_GATTS_CONNECT_EVT event.

LMK if you need additional information.

Here is a printout of the test showing some of the reasons:

I (470781) GATTS_DEMO: ESP_GATTS_CONNECT_EVT, conn_id 0, remote 61:18:54:cd:23:5b:
I (470791) GATTS_DEMO: CONNECT_EVT, conn_id 0, remote 61:18:54:cd:23:5b:
I (471471) GATTS_DEMO: update connetion params status = 0, min_int = 16, max_int = 32,conn_int = 24,latency = 0, timeout = 400
I (471751) GATTS_DEMO: update connetion params status = 0, min_int = 0, max_int = 0,conn_int = 6,latency = 0, timeout = 2000
I (472041) GATTS_DEMO: update connetion params status = 0, min_int = 0, max_int = 0,conn_int = 24,latency = 0, timeout = 400
I (479691) GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT, reason 8
I (480781) GATTS_DEMO: ESP_GATTS_CONNECT_EVT, conn_id 0, remote 61:18:54:cd:23:5b:
I (480781) GATTS_DEMO: CONNECT_EVT, conn_id 0, remote 61:18:54:cd:23:5b:
I (480971) GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT, reason 19
I (481271) GATTS_DEMO: ESP_GATTS_CONNECT_EVT, conn_id 0, remote 61:18:54:cd:23:5b:
I (481271) GATTS_DEMO: CONNECT_EVT, conn_id 0, remote 61:18:54:cd:23:5b:
I (483271) GATTS_DEMO: update connetion params status = 16, min_int = 16, max_int = 32,conn_int = 39,latency = 0, timeout = 2000
I (494621) GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT, reason 31
I (495741) GATTS_DEMO: ESP_GATTS_CONNECT_EVT, conn_id 0, remote 61:18:54:cd:23:5b:
I (495741) GATTS_DEMO: CONNECT_EVT, conn_id 0, remote 61:18:54:cd:23:5b:
I (496281) GATTS_DEMO: update connetion params status = 0, min_int = 16, max_int = 32,conn_int = 24,latency = 0, timeout = 400
I (496591) GATTS_DEMO: update connetion params status = 0, min_int = 0, max_int = 0,conn_int = 6,latency = 0, timeout = 2000
I (496881) GATTS_DEMO: update connetion params status = 0, min_int = 0, max_int = 0,conn_int = 24,latency = 0, timeout = 400
I (504661) GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT, reason 8
I (505791) GATTS_DEMO: ESP_GATTS_CONNECT_EVT, conn_id 0, remote 61:18:54:cd:23:5b:
I (505791) GATTS_DEMO: CONNECT_EVT, conn_id 0, remote 61:18:54:cd:23:5b:
I (506041) GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT, reason 19
I (506321) GATTS_DEMO: ESP_GATTS_CONNECT_EVT, conn_id 0, remote 61:18:54:cd:23:5b:
I (506321) GATTS_DEMO: CONNECT_EVT, conn_id 0, remote 61:18:54:cd:23:5b:
I (508331) GATTS_DEMO: update connetion params status = 16, min_int = 16, max_int = 32,conn_int = 39,latency = 0, timeout = 2000
I (526331) GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT, reason 8
I (530751) GATTS_DEMO: ESP_GATTS_CONNECT_EVT, conn_id 0, remote 61:18:54:cd:23:5b:
I (530751) GATTS_DEMO: CONNECT_EVT, conn_id 0, remote 61:18:54:cd:23:5b:
I (531351) GATTS_DEMO: update connetion params status = 0, min_int = 16, max_int = 32,conn_int = 24,latency = 0, timeout = 400
I (531631) GATTS_DEMO: update connetion params status = 0, min_int = 0, max_int = 0,conn_int = 6,latency = 0, timeout = 2000
I (531951) GATTS_DEMO: update connetion params status = 0, min_int = 0, max_int = 0,conn_int = 24,latency = 0, timeout = 400

Weijian-Espressif commented 6 years ago

@ayavilevich I use "Connect with autoConnect" to test our gatt_server demo with nrf connect APP. it works well , my phone is HUAWEI Mate 8, IDF commit is 9e8d0982642669fa0c10210a0dce49d549cb2ef9, here is the log:

I (595) GATTS_DEMO: prf_char[2] =33

I (595) GATTS_DEMO: ADD_DESCR_EVT, status 0, attr_handle 43, service_handle 40

I (605) GATTS_DEMO: REGISTER_APP_EVT, status 0, app_id 1

I (615) GATTS_DEMO: CREATE_SERVICE_EVT, status 0, service_handle 44

I (625) GATTS_DEMO: SERVICE_START_EVT, status 0, service_handle 44

I (625) GATTS_DEMO: ADD_CHAR_EVT, status 0, attr_handle 46, service_handle 44

I (635) GATTS_DEMO: ADD_DESCR_EVT, status 0, attr_handle 47, service_handle 44

I (16025) GATTS_DEMO: ESP_GATTS_CONNECT_EVT, conn_id 0, remote 7e:3f:b6:b7:ca:fb: I (16025) GATTS_DEMO: CONNECT_EVT, conn_id 0, remote 7e:3f:b6:b7:ca:fb: I (17035) GATTS_DEMO: update connetion params status = 16, min_int = 16, max_int = 32,conn_int = 0,latency = 0, timeout = 0 I (17405) GATTS_DEMO: update connetion params status = 0, min_int = 0, max_int = 0,conn_int = 24,latency = 0, timeout = 400 I (17835) GATTS_DEMO: update connetion params status = 0, min_int = 0, max_int = 0,conn_int = 6,latency = 0, timeout = 2000 I (18245) GATTS_DEMO: update connetion params status = 0, min_int = 0, max_int = 0,conn_int = 24,latency = 0, timeout = 400 I (56945) GATTS_DEMO: GATT_READ_EVT, conn_id 0, trans_id 1, handle 42

I (58625) GATTS_DEMO: GATT_READ_EVT, conn_id 0, trans_id 2, handle 42

I (60035) GATTS_DEMO: GATT_READ_EVT, conn_id 0, trans_id 3, handle 42

I (63095) GATTS_DEMO: GATT_READ_EVT, conn_id 0, trans_id 4, handle 42

ayavilevich commented 6 years ago

@Weijian-Espressif What Android version is on the phone? I have LG G4 with Android 6.0.

Did you also add the line: esp_ble_gap_start_advertising(&adv_params); to ~~ESP_GATTS_DISCONNECT_EVT~~ ESP_GATTS_CONNECT_EVT?

Weijian-Espressif commented 6 years ago

@ayavilevich my phone is HUAWEI Mate 8 with Android 7.0, our gatt_server demo have already add esp_ble_gap_start_advertising(&adv_params) to ESP_GATTS_DISCONNECT_EVT.

ayavilevich commented 6 years ago

@Weijian-Espressif Ok, I see where we are different. I messed up the last two updates. I meant esp_ble_gap_start_advertising(&adv_params); in ESP_GATTS_CONNECT_EVT. There is a restart in ESP_GATTS_DISCONNECT_EVT in the original code that I didn't change. I am restarting advertising after a connect to allow for multi-connect.

Only if "autoConnect" and restart of advertising after a connect then I am seeing the issue. Please try on your end,

ayavilevich commented 6 years ago

This is the specific code block to clear any confusion

    case ESP_GATTS_CONNECT_EVT: {
        esp_ble_conn_update_params_t conn_params = {0};
        memcpy(conn_params.bda, param->connect.remote_bda, sizeof(esp_bd_addr_t));
        /* For the IOS system, please reference the apple official documents about the ble connection parameters restrictions. */
        conn_params.latency = 0;
        conn_params.max_int = 0x20;    // max_int = 0x20*1.25ms = 40ms
        conn_params.min_int = 0x10;    // min_int = 0x10*1.25ms = 20ms
        conn_params.timeout = 400;    // timeout = 400*10ms = 4000ms
        ESP_LOGI(GATTS_TAG, "ESP_GATTS_CONNECT_EVT, conn_id %d, remote %02x:%02x:%02x:%02x:%02x:%02x:",
                 param->connect.conn_id,
                 param->connect.remote_bda[0], param->connect.remote_bda[1], param->connect.remote_bda[2],
                 param->connect.remote_bda[3], param->connect.remote_bda[4], param->connect.remote_bda[5]);
        gl_profile_tab[PROFILE_A_APP_ID].conn_id = param->connect.conn_id;
        //start sent the update connection parameters to the peer device.
        esp_ble_gap_update_conn_params(&conn_params);

        // ADD
        esp_ble_gap_start_advertising(&adv_params); // advertise once again
        // ~ADD
        break;
    }
    case ESP_GATTS_DISCONNECT_EVT:
        ESP_LOGI(GATTS_TAG, "ESP_GATTS_DISCONNECT_EVT, reason %d", param->disconnect.reason);
        esp_ble_gap_start_advertising(&adv_params);
        break;

Weijian-Espressif commented 6 years ago

I only have LG G5, I use LG G5 with 6.0.1, this is the test code : case ESP_GATTS_CONNECT_EVT: { esp_ble_conn_update_params_t conn_params = {0}; memcpy(conn_params.bda, param->connect.remote_bda, sizeof(esp_bd_addr_t)); / For the IOS system, please reference the apple official documents about the ble connection parameters restrictions. / conn_params.latency = 0; conn_params.max_int = 0x20; // max_int = 0x201.25ms = 40ms conn_params.min_int = 0x10; // min_int = 0x101.25ms = 20ms conn_params.timeout = 400; // timeout = 400*10ms = 4000ms ESP_LOGI(GATTS_TAG, "ESP_GATTS_CONNECT_EVT, conn_id %d, remote %02x:%02x:%02x:%02x:%02x:%02x:", param->connect.conn_id, param->connect.remote_bda[0], param->connect.remote_bda[1], param->connect.remote_bda[2], param->connect.remote_bda[3], param->connect.remote_bda[4], param->connect.remote_bda[5]); gl_profile_tab[PROFILE_A_APP_ID].conn_id = param->connect.conn_id; //start sent the update connection parameters to the peer device. esp_ble_gap_update_conn_params(&conn_params); esp_ble_gap_start_advertising(&adv_params); break; } case ESP_GATTS_DISCONNECT_EVT: ESP_LOGI(GATTS_TAG, "ESP_GATTS_DISCONNECT_EVT"); esp_ble_gap_start_advertising(&adv_params); break;

it work well , this is the log: I (565) GATTS_DEMO: REGISTER_APP_EVT, status 0, app_id 0

I (565) GATTS_DEMO: CREATE_SERVICE_EVT, status 0, service_handle 40

E (575) GATTS_DEMO: ----------Advertising start successfully

I (575) GATTS_DEMO: SERVICE_START_EVT, status 0, service_handle 40

I (575) GATTS_DEMO: ADD_CHAR_EVT, status 0, attr_handle 42, service_handle 40

I (585) GATTS_DEMO: the gatts demo char length = 3

I (595) GATTS_DEMO: prf_char[0] =11

I (595) GATTS_DEMO: prf_char[1] =22

I (605) GATTS_DEMO: prf_char[2] =33

I (605) GATTS_DEMO: ADD_DESCR_EVT, status 0, attr_handle 43, service_handle 40

I (615) GATTS_DEMO: REGISTER_APP_EVT, status 0, app_id 1

I (615) GATTS_DEMO: CREATE_SERVICE_EVT, status 0, service_handle 44

I (625) GATTS_DEMO: SERVICE_START_EVT, status 0, service_handle 44

I (635) GATTS_DEMO: ADD_CHAR_EVT, status 0, attr_handle 46, service_handle 44

I (645) GATTS_DEMO: ADD_DESCR_EVT, status 0, attr_handle 47, service_handle 44

I (18605) GATTS_DEMO: ESP_GATTS_CONNECT_EVT, conn_id 0, remote 77:31:ae:14:c1:cf: I (18605) GATTS_DEMO: CONNECT_EVT, conn_id 0, remote 77:31:ae:14:c1:cf: E (18615) GATTS_DEMO: ----------Advertising start successfully

I (19605) GATTS_DEMO: update connetion params status = 16, min_int = 16, max_int = 32,conn_int = 0,latency = 0, timeout = 0 I (19795) GATTS_DEMO: update connetion params status = 0, min_int = 0, max_int = 0,conn_int = 24,latency = 0, timeout = 400 I (20135) GATTS_DEMO: update connetion params status = 0, min_int = 0, max_int = 0,conn_int = 6,latency = 0, timeout = 2000 I (20695) GATTS_DEMO: update connetion params status = 0, min_int = 0, max_int = 0,conn_int = 24,latency = 0, timeout = 400 I (23845) GATTS_DEMO: GATT_READ_EVT, conn_id 0, trans_id 1, handle 42

I (25375) GATTS_DEMO: GATT_READ_EVT, conn_id 0, trans_id 2, handle 42

I (25825) GATTS_DEMO: GATT_READ_EVT, conn_id 0, trans_id 3, handle 42

I (26095) GATTS_DEMO: GATT_READ_EVT, conn_id 0, trans_id 4, handle 42

ayavilevich commented 6 years ago

@Weijian-Espressif

LG G5 with Android 6.0 should be good to reproduce this.

Where to add ----------Advertising start successfully so I also have the same printout?

I have done more testing and identified another required factor. The Android device should also try to autoConnect to another device (MAC#) at the same time and the second device needs to be offline.

Here are the latest reproduce instructions:

Have two BLE devices, device A is ESP32 with the above described modified gatt_server code and device B which can also be ESP32 but it doesn't matter.
If the devices are not in nRF list, power on both devices and scan from nRF so they are in the device list.
Power down device B, while device A is powered on.
autoConnect to device B. This should not complete right away and should continue in the background.
autoConnect to device A.
You should now have disconnects for device A. I have seen disconnect reasons: 8, 31, 34.

Hope you can reproduce this time. Thanks for the effort.

mws-rmain commented 6 years ago

I believe @Weijan-Espressif added the additional tag in function gap_event_handler() as shown below:

    case ESP_GAP_BLE_ADV_START_COMPLETE_EVT:
        //advertising start complete event to indicate advertising start successfully or failed
        if (param->adv_start_cmpl.status != ESP_BT_STATUS_SUCCESS) {
            ESP_LOGE(GATTS_TAG, "Advertising start failed\n");
        } else {
            ESP_LOGE(GATTS_TAG, "----------Advertising start successfully\n");
        }

I don't want to hijack your diagnostics on this issue, but I'm experiencing a similar issue on my LG G5 (unexpected disconnects) using custom BLE server code on an ESP32. In my case, the disconnect occurs before all services are even discovered, using nRF Connect on my G5. The same device works fine if I connect with nRF Connect on a Google Pixel 1, or my old Nexus 4 (ironically made by LG). I added your patch to re-start advertising at the end of ESP_GATTS_CONNECT_EVT in the gatts_profile_a_event_handler().

I simply connected the the server, then disconnected about 30 seconds later.

Console Log (LG G5):

--- idf_monitor on /dev/ttyUSB0 115200 ---
--- Quit: Ctrl+] | Menu: Ctrl+T | Help: Ctrl+T followed by Ctrl+H ---
ets Jun  8 2016 00:22:57

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
ets Jun  8 2016 00:22:57

rst:0x10 (RTCWDT_RTC_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:2
load:0x3fff0018,len:4
load:0x3fff001c,len:5548
load:0x40078000,len:0
load:0x40078000,len:12636
entry 0x40078fe4
I (28) boot: ESP-IDF v3.1-dev-463-g77eae33 2nd stage bootloader
I (28) boot: compile time 08:24:26
I (28) boot: Enabling RNG early entropy source...
I (34) boot: SPI Speed      : 40MHz
I (38) boot: SPI Mode       : DIO
I (42) boot: SPI Flash Size : 4MB
I (46) boot: Partition Table:
I (50) boot: ## Label            Usage          Type ST Offset   Length
I (57) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (65) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (72) boot:  2 factory          factory app      00 00 00010000 00100000
I (80) boot: End of partition table
I (84) esp_image: segment 0: paddr=0x00010020 vaddr=0x3f400020 size=0x291c4 (168388) map
I (152) esp_image: segment 1: paddr=0x000391ec vaddr=0x3ffc0000 size=0x02884 ( 10372) load
I (156) esp_image: segment 2: paddr=0x0003ba78 vaddr=0x40080000 size=0x00400 (  1024) load
0x40080000: _iram_start at /home/mainr/esp/esp-idf/components/freertos/./xtensa_vectors.S:1685

I (159) esp_image: segment 3: paddr=0x0003be80 vaddr=0x40080400 size=0x04190 ( 16784) load
I (174) esp_image: segment 4: paddr=0x00040018 vaddr=0x400d0018 size=0x68268 (426600) map
0x400d0018: _stext at ??:?

I (325) esp_image: segment 5: paddr=0x000a8288 vaddr=0x40084590 size=0x084b0 ( 33968) load
0x40084590: r_ld_acl_ssr_set at ??:?

I (339) esp_image: segment 6: paddr=0x000b0740 vaddr=0x400c0000 size=0x00000 (     0) load
I (347) boot: Loaded app from partition at offset 0x10000
I (347) boot: Disabling RNG early entropy source...
I (349) cpu_start: Pro cpu up.
I (352) cpu_start: Starting app cpu, entry point is 0x40081118
0x40081118: call_start_cpu1 at /home/mainr/esp/esp-idf/components/esp32/./cpu_start.c:225

I (0) cpu_start: App cpu up.
I (363) heap_init: Initializing. RAM available for dynamic allocation:
I (370) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
I (376) heap_init: At 3FFCA8D8 len 00015728 (85 KiB): DRAM
I (382) heap_init: At 3FFE0440 len 00003BC0 (14 KiB): D/IRAM
I (388) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (395) heap_init: At 4008CA40 len 000135C0 (77 KiB): IRAM
I (401) cpu_start: Pro cpu start user code
I (83) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (227) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (537) phy: phy_version: 383.0, 79a622c, Jan 30 2018, 15:38:06, 0, 0
I (567) GATTS_DEMO: REGISTER_APP_EVT, status 0, app_id 0

I (567) GATTS_DEMO: CREATE_SERVICE_EVT, status 0,  service_handle 40

E (577) GATTS_DEMO: ----------Advertising start successfully

I (577) GATTS_DEMO: SERVICE_START_EVT, status 0, service_handle 40

I (577) GATTS_DEMO: ADD_CHAR_EVT, status 0,  attr_handle 42, service_handle 40

I (587) GATTS_DEMO: the gatts demo char length = 3

I (597) GATTS_DEMO: prf_char[0] =11

I (597) GATTS_DEMO: prf_char[1] =22

I (607) GATTS_DEMO: prf_char[2] =33

I (607) GATTS_DEMO: ADD_DESCR_EVT, status 0, attr_handle 43, service_handle 40

I (617) GATTS_DEMO: REGISTER_APP_EVT, status 0, app_id 1

I (627) GATTS_DEMO: CREATE_SERVICE_EVT, status 0,  service_handle 44

I (627) GATTS_DEMO: SERVICE_START_EVT, status 0, service_handle 44

I (637) GATTS_DEMO: ADD_CHAR_EVT, status 0,  attr_handle 46, service_handle 44

I (647) GATTS_DEMO: ADD_DESCR_EVT, status 0, attr_handle 47, service_handle 44

I (78337) GATTS_DEMO: ESP_GATTS_CONNECT_EVT, conn_id 0, remote 4b:43:6d:16:a1:21:
I (78337) GATTS_DEMO: CONNECT_EVT, conn_id 0, remote 4b:43:6d:16:a1:21:
E (78347) GATTS_DEMO: ----------Advertising start successfully

I (78977) GATTS_DEMO: update connetion params status = 0, min_int = 16, max_int = 32,conn_int = 24,latency = 0, timeout = 400
I (105197) GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT
E (105207) GATTS_DEMO: ----------Advertising start successfully

nRF Log:

nRF Connect, 2018-03-21
ESP_GATTS_DEMO (24:0A:C4:07:22:D2)
V   10:02:53.777    Connecting to 24:0A:C4:07:22:D2...
D   10:02:53.783    gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE)
D   10:02:58.040    [Server callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I   10:02:58.041    [Server] Device with address 24:0A:C4:07:22:D2 connected
V   10:02:58.041    [Server] Creating server connection...
D   10:02:58.041    server.connect(device, autoConnect = false)
D   10:02:58.051    [Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I   10:02:58.051    Connected to 24:0A:C4:07:22:D2
D   10:02:58.075    [Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
V   10:02:58.075    Discovering services...
D   10:02:58.075    gatt.discoverServices()
D   10:02:58.106    [Callback] Services discovered with status: 0
I   10:02:58.106    Services discovered
V   10:02:58.113    Generic Attribute (0x1801)
            - Service Changed [I] (0x2A05)
            Generic Access (0x1800)
            - Device Name [R] (0x2A00)
            - Appearance [R] (0x2A01)
            - Central Address Resolution [R] (0x2AA6)
V   10:03:24.772    [Server] Cancelling server connection...
D   10:03:24.772    server.cancelConnection(device)
V   10:03:24.775    Disconnecting...
D   10:03:24.775    gatt.disconnect()
D   10:03:24.781    [Server callback] Connection state changed with status: 0 and new state: DISCONNECTED (0)
I   10:03:24.781    [Server] Device disconnected
D   10:03:24.781    [Callback] Connection state changed with status: 0 and new state: DISCONNECTED (0)
I   10:03:24.781    Disconnected
D   10:03:24.839    [Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED

Note the '[Server] Cancelling server connection' event. Nothing was done to invoke this. I believe this is due to a broken Bluetooth stack in the LG G5.

Below is the nRF Log from accessing the same device with the Pixel 1:

nRF Connect, 2018-03-21
ESP_GATTS_DEMO (24:0A:C4:07:22:D2)
V   10:39:57.780    Connecting to 24:0A:C4:07:22:D2...
D   10:39:57.780    gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferred PHY = LE 1M)
D   10:39:57.976    [Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I   10:39:57.976    Connected to 24:0A:C4:07:22:D2
D   10:39:57.977    [Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
V   10:39:58.011    Discovering services...
D   10:39:58.011    gatt.discoverServices()
I   10:39:58.690    Connection parameters updated (interval: 37.5ms, latency: 0, timeout: 4000ms)
I   10:39:59.224    Connection parameters updated (interval: 7.5ms, latency: 0, timeout: 5000ms)
D   10:39:59.357    [Callback] Services discovered with status: 0
I   10:39:59.360    Services discovered
V   10:39:59.376    Generic Attribute (0x1801)
            - Service Changed [I] (0x2A05)
            Generic Access (0x1800)
            - Device Name [R] (0x2A00)
            - Appearance [R] (0x2A01)
            - Central Address Resolution [R] (0x2AA6)
            Unknown Service (000000ff-0000-1000-8000-00805f9b34fb)
            - Unknown Characteristic [N R W] (0000ff01-0000-1000-8000-00805f9b34fb)
               Client Characteristic Configuration (0x2902)
            Unknown Service (000000ee-0000-1000-8000-00805f9b34fb)
            - Unknown Characteristic [N R W] (0000ee01-0000-1000-8000-00805f9b34fb)
               Client Characteristic Configuration (0x2902)
I   10:39:59.442    Connection parameters updated (interval: 37.5ms, latency: 0, timeout: 4000ms)
V   10:40:21.200    Disconnecting...
D   10:40:21.200    gatt.disconnect()
D   10:40:21.205    [Callback] Connection state changed with status: 0 and new state: DISCONNECTED (0)
I   10:40:21.205    Disconnected
D   10:40:22.296    [Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED

Note the additional attributes listed during discovery. The two [screenshots are here:]() Again, please note the additional attributes displayed. I'm not sure if this is at all related to your issue. Perhaps I should be posting this as a new issue, and simply referencing your issue (?).

Note: My G5 is running Android 7.0. The Pixel is running Android 8.1.0.

mws-rmain commented 6 years ago

A little more clarity. The log below is again from my LG G5, but I waited & timed my actions so I could use the timestamps in the log to determine when things occurred. The log below shows records I had stripped from the one above, because I thought they were irrelevant (collected while nRF Connect was 'scanning' for devices). These records appear to show a mixture of attributes from every BLE device within range. The Pixel does not show ANY of this. These records appear in the log when I select the 'ESP_GATTS_DEMO' device from the scan list. What's really weird is that it lists these attributes are listed before the record that indicates it is attempting to connect to the ESP.

Finally, the '[Server] Cancelling Server Connection...' record appears when I touch 'disconnect' (2 minutes later), so it has nothing to with the truncated service discovery process.

nRF Connect, 2018-03-21
ESP_GATTS_DEMO (24:0A:C4:07:22:D2)
I   11:50:08.081    [Server] Server started
V   11:50:08.111    Unknown Service (3ab10100-f831-4395-b29d-570977d5bf94)
            - Unknown Characteristic [I R] (3ab10101-f831-4395-b29d-570977d5bf94)
               Client Characteristic Configuration (0x2902)
            - Unknown Characteristic [I R] (3ab10102-f831-4395-b29d-570977d5bf94)
               Client Characteristic Configuration (0x2902)
            - Unknown Characteristic [I R] (3ab10103-f831-4395-b29d-570977d5bf94)
               Client Characteristic Configuration (0x2902)
            - Unknown Characteristic [I R] (3ab10104-f831-4395-b29d-570977d5bf94)
               Client Characteristic Configuration (0x2902)
            - Unknown Characteristic [I R] (3ab10105-f831-4395-b29d-570977d5bf94)
               Client Characteristic Configuration (0x2902)
            - Unknown Characteristic [WNR] (3ab10109-f831-4395-b29d-570977d5bf94)
            - Unknown Characteristic [I R] (3ab1010a-f831-4395-b29d-570977d5bf94)
               Client Characteristic Configuration (0x2902)
            - Unknown Characteristic [R] (3ab1010c-f831-4395-b29d-570977d5bf94)
            Human Interface Device (0x1812)
            - Report [N R] (0x2A4D)
               Report Reference (0x2908)
               Client Characteristic Configuration (0x2902)
            - Report [N R] (0x2A4D)
               Report Reference (0x2908)
               Client Characteristic Configuration (0x2902)
            - HID Information [R] (0x2A4A)
            - Protocol Mode [R WNR] (0x2A4E)
            - HID Control Point [WNR] (0x2A4C)
            - Report Map [R] (0x2A4B)
            - Report [R W WNR] (0x2A4D)
               Report Reference (0x2908)
            - Boot Keyboard Input Report [N R] (0x2A22)
               Client Characteristic Configuration (0x2902)
            - Boot Keyboard Output Report [R W WNR] (0x2A32)
            Battery Service (0x180F)
            - Battery Level [R] (0x2A19)
            - Battery Power State [R] (0x2A1A)
            Scan Parameters (0x1813)
            - Scan Interval Window [WNR] (0x2A4F)
            - Scan Refresh [N] (0x2A31)
               Client Characteristic Configuration (0x2902)
            Device Information (0x180A)
            - PnP ID [R] (0x2A50)
            - Hardware Revision String [R] (0x2A27)
V   11:50:08.484    Connecting to 24:0A:C4:07:22:D2...
D   11:50:08.484    gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE)
D   11:50:13.137    [Server callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I   11:50:13.137    [Server] Device with address 24:0A:C4:07:22:D2 connected
V   11:50:13.138    [Server] Creating server connection...
D   11:50:13.138    server.connect(device, autoConnect = false)
D   11:50:13.151    [Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I   11:50:13.151    Connected to 24:0A:C4:07:22:D2
D   11:50:13.176    [Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
V   11:50:13.178    Discovering services...
D   11:50:13.178    gatt.discoverServices()
D   11:50:13.186    [Callback] Services discovered with status: 0
I   11:50:13.186    Services discovered
V   11:50:13.198    Generic Attribute (0x1801)
            - Service Changed [I] (0x2A05)
            Generic Access (0x1800)
            - Device Name [R] (0x2A00)
            - Appearance [R] (0x2A01)
            - Central Address Resolution [R] (0x2AA6)
V   11:52:18.243    [Server] Cancelling server connection...
D   11:52:18.243    server.cancelConnection(device)
V   11:52:18.247    Disconnecting...
D   11:52:18.247    gatt.disconnect()
D   11:52:18.253    [Callback] Connection state changed with status: 0 and new state: DISCONNECTED (0)
I   11:52:18.253    Disconnected
D   11:52:18.254    [Server callback] Connection state changed with status: 0 and new state: DISCONNECTED (0)
I   11:52:18.254    [Server] Device disconnected
D   11:52:18.315    [Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED

Weijian-Espressif commented 6 years ago

@ayavilevich @mws-rmain from the nRF Log , I found nrf disconnect the connection. Do you have the source code of nRF?

V 11:52:18.243 [Server] Cancelling server connection... D 11:52:18.243 server.cancelConnection(device) V 11:52:18.247 Disconnecting... D 11:52:18.247 gatt.disconnect() D 11:52:18.253 [Callback] Connection state changed with status: 0 and new state: DISCONNECTED (0) I 11:52:18.253 Disconnected D 11:52:18.254 [Server callback] Connection state changed with status: 0 and new state: DISCONNECTED (0) I 11:52:18.254 [Server] Device disconnected D 11:52:18.315 [Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED

V21:42:06.948Disconnecting... D21:42:06.948gatt.disconnect() D21:42:06.970[Callback] Connection state changed with status: 0 and new state: DISCONNECTED (0) I21:42:06.970Disconnected D21:42:06.971gatt.refresh() (hidden) D21:42:06.978gatt.close() D21:42:06.981wait(200) D21:42:07.042[Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED

ayavilevich commented 6 years ago

@mws-rmain your issue seems to be different from mine. Though both feature disconnects and the LG G5 phone, mine happens much quicker and only happens if I autoConnect=true and re-enable advertizing. Therefore it would have been better to create a separate issue to what you are experiencing and link the two.

I don't experience issues if I use regular connect (autoConnect = false) . For example, this is part of my log:

V21:41:16.054Connecting to 30:AE:A4:36:82:3A...
D21:41:16.054gatt = device.connectGatt(autoConnect = true, TRANSPORT_LE)
D21:41:18.705[Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I21:41:18.705Connected to 30:AE:A4:36:82:3A

Also, my disconnects are in 10 or less seconds from a connect and are typically TIMEOUT not "[Server] Cancelling server connection...". Again, see this log:

D21:41:42.999[Callback] Services discovered with status: 0
I21:41:43.001Services discovered
V21:41:43.027Generic Attribute (0x1801)
- Service Changed [I] (0x2A05)
Generic Access (0x1800)
- Device Name [R] (0x2A00)
- Appearance [R] (0x2A01)
- Central Address Resolution [R] (0x2AA6)
Unknown Service (000000ff-0000-1000-8000-00805f9b34fb)
- Unknown Characteristic [N R W] (0000ff01-0000-1000-8000-00805f9b34fb)
   Client Characteristic Configuration (0x2902)
Unknown Service (000000ee-0000-1000-8000-00805f9b34fb)
- Unknown Characteristic [N R W] (0000ee01-0000-1000-8000-00805f9b34fb)
   Client Characteristic Configuration (0x2902)
D21:41:47.756[Callback] Connection state changed with status: 8 and new state: DISCONNECTED (0)
E21:41:47.756Error 8 (0x8): GATT CONN TIMEOUT
I21:41:47.756Disconnected

If you post a new issue with a detailed minimal reproduce instruction (including were to take the code and what changes if any to make) I will try to reproduce on the LG G4/G5 that I have available here. I will be glad if you try to reproduce my multi-connect scenario. Disconnect happen in 3-10 seconds, not 30.

@Weijian-Espressif these seems to be two different issues. Have you tried to reproduce the one I described?

The nRF Connect source code should be available here: https://github.com/NordicSemiconductor/Android-nRF-Connect/ . Might be complex for a minimal reproduce case.

I can provide a simple Android app source code that can be used on the Android side instead of nRF to reproduce my multi-connect issue. Let me know if you would like to get that and where to send/upload it.

Weijian-Espressif commented 6 years ago

@ayavilevich sorry, I can not reproduce the issue with LG G5. what is the commit of ESP-IDF? Could you give me you ESP32 code?

ayavilevich commented 6 years ago

@Weijian-Espressif

:( Sad it doesn't reproduce. Did you try to connect to two devices at the same time where one is not powered?

I was at commit 77eae33a (March 9). I was sure I was on a more recent one. Just updated to 84788230 (March 21) and tested again. Still experiencing the issue.

My ESP32 code: https://pastebin.com/jLFVPw4L

What is disconnect reason "31" (decimal) that sometimes happen? Does it provide some information about the issue?

Here is latest console monitor:

I (508) GATTS_DEMO: prf_char[1] =22

I (508) GATTS_DEMO: prf_char[2] =33

I (518) GATTS_DEMO: ADD_DESCR_EVT, status 0, attr_handle 43, service_handle 40

I (528) GATTS_DEMO: REGISTER_APP_EVT, status 0, app_id 1

I (528) GATTS_DEMO: CREATE_SERVICE_EVT, status 0,  service_handle 44

I (538) GATTS_DEMO: SERVICE_START_EVT, status 0, service_handle 44

I (548) GATTS_DEMO: ADD_CHAR_EVT, status 0,  attr_handle 46, service_handle 44

I (548) GATTS_DEMO: ADD_DESCR_EVT, status 0, attr_handle 47, service_handle 44

I (4628) GATTS_DEMO: ESP_GATTS_CONNECT_EVT, conn_id 0, remote 7b:f5:05:61:cf:50:
I (4628) GATTS_DEMO: ----------Advertising once again
I (4628) GATTS_DEMO: CONNECT_EVT, conn_id 0, remote 7b:f5:05:61:cf:50:
I (4648) GATTS_DEMO: ----------Advertising start successfully
I (5238) GATTS_DEMO: update connection params status = 0, min_int = 16, max_int = 32,conn_int = 24,latency = 0, timeout = 400
I (5518) GATTS_DEMO: update connection params status = 0, min_int = 0, max_int = 0,conn_int = 6,latency = 0, timeout = 2000
I (5848) GATTS_DEMO: update connection params status = 0, min_int = 0, max_int = 0,conn_int = 24,latency = 0, timeout = 400
I (13488) GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT, reason 8
I (13488) GATTS_DEMO: ----------Advertising start successfully
I (14618) GATTS_DEMO: ESP_GATTS_CONNECT_EVT, conn_id 0, remote 7b:f5:05:61:cf:50:
I (14628) GATTS_DEMO: ----------Advertising once again
I (14628) GATTS_DEMO: CONNECT_EVT, conn_id 0, remote 7b:f5:05:61:cf:50:
I (14638) GATTS_DEMO: ----------Advertising start successfully
I (15228) GATTS_DEMO: update connection params status = 0, min_int = 16, max_int = 32,conn_int = 24,latency = 0, timeout = 400
I (23478) GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT, reason 8
I (23488) GATTS_DEMO: ----------Advertising start successfully
I (24628) GATTS_DEMO: ESP_GATTS_CONNECT_EVT, conn_id 0, remote 7b:f5:05:61:cf:50:
I (24628) GATTS_DEMO: ----------Advertising once again
I (24628) GATTS_DEMO: CONNECT_EVT, conn_id 0, remote 7b:f5:05:61:cf:50:
I (24638) GATTS_DEMO: ----------Advertising start successfully
I (24818) GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT, reason 19
I (24828) GATTS_DEMO: ----------Advertising start successfully
I (29628) GATTS_DEMO: ESP_GATTS_CONNECT_EVT, conn_id 0, remote 7b:f5:05:61:cf:50:
I (29628) GATTS_DEMO: ----------Advertising once again
I (29638) GATTS_DEMO: CONNECT_EVT, conn_id 0, remote 7b:f5:05:61:cf:50:
I (29648) GATTS_DEMO: ----------Advertising start successfully
I (30228) GATTS_DEMO: update connection params status = 0, min_int = 16, max_int = 32,conn_int = 24,latency = 0, timeout = 400
I (30508) GATTS_DEMO: update connection params status = 0, min_int = 0, max_int = 0,conn_int = 6,latency = 0, timeout = 2000
I (30828) GATTS_DEMO: update connection params status = 0, min_int = 0, max_int = 0,conn_int = 24,latency = 0, timeout = 400
I (38518) GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT, reason 8
I (38518) GATTS_DEMO: ----------Advertising start successfully
I (39578) GATTS_DEMO: ESP_GATTS_CONNECT_EVT, conn_id 0, remote 7b:f5:05:61:cf:50:
I (39578) GATTS_DEMO: ----------Advertising once again
I (39578) GATTS_DEMO: CONNECT_EVT, conn_id 0, remote 7b:f5:05:61:cf:50:
I (39588) GATTS_DEMO: ----------Advertising start successfully
I (40188) GATTS_DEMO: update connection params status = 0, min_int = 16, max_int = 32,conn_int = 24,latency = 0, timeout = 400
I (48538) GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT, reason 8
I (48538) GATTS_DEMO: ----------Advertising start successfully
I (49578) GATTS_DEMO: ESP_GATTS_CONNECT_EVT, conn_id 0, remote 7b:f5:05:61:cf:50:
I (49578) GATTS_DEMO: ----------Advertising once again
I (49588) GATTS_DEMO: CONNECT_EVT, conn_id 0, remote 7b:f5:05:61:cf:50:
I (49598) GATTS_DEMO: ----------Advertising start successfully
I (50268) GATTS_DEMO: update connection params status = 0, min_int = 16, max_int = 32,conn_int = 24,latency = 0, timeout = 400
I (58498) GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT, reason 8

mws-rmain commented 6 years ago

@Weijian-Espressif As I mentioned in the post, the server disconnect shown in the log was a direct result of my pressing 'disconnect', not any automatic action, so it can be discounted. The time-stamps show the disconnect occurred 2 minutes after the connect. I intentionally waited before pressing disconnect so I could use the timestamp to confirm it was due to intentional action.

Also, I do not have nRF Connect source code. Nordic has never released it.

@ayavilevich Followed your Nordic link. See the line: Note: The source code of nRF Connect is not available. I am also at March 9 git commit - I will update & retry.

I verified my gatt server code against yours from pastebin, and found only minor differences in diagnostics. Could you also post your sdkconfig ? I assume you're running defaults, including default BT config, and default loglevel (INFO - as increasing this requires significantly larger stack).

I will try to take a quick kick at reproducing your 'autoconnect=true' and multiple phones scenario, but I don't expect to see the same results. With a single connection, you are able to see the extended attributes, whereas my G5 doesn't. Since we're both running Android 7.0 & nRF Connect on an LG G5, and the same code on ESP32, I don't see where the variation is coming from.

ayavilevich commented 6 years ago

@mws-rmain you are right about nRF source code. Seems the repository is just for docs...

Regarding your disconnect. You posted:

V   10:02:58.075    Discovering services...
D   10:02:58.075    gatt.discoverServices()
D   10:02:58.106    [Callback] Services discovered with status: 0
I   10:02:58.106    Services discovered
V   10:02:58.113    Generic Attribute (0x1801)
            - Service Changed [I] (0x2A05)
            Generic Access (0x1800)
            - Device Name [R] (0x2A00)
            - Appearance [R] (0x2A01)
            - Central Address Resolution [R] (0x2AA6)
V   10:03:24.772    [Server] Cancelling server connection...
D   10:03:24.772    server.cancelConnection(device)
V   10:03:24.775    Disconnecting...
D   10:03:24.775    gatt.disconnect()

and wrote "Note the '[Server] Cancelling server connection' event. Nothing was done to invoke this. I believe this is due to a broken Bluetooth stack in the LG G5." . This is what I based my response on and this is different from what happens here. However, I am not testing the same use case and it disconnects much earlier for me, so perhaps if my issue would have not occurred then I would have experienced your issue. As I wrote, I am happy to try and reproduce. Please send/post minimal reproduce instructions.

Take a look at my sdkconfig https://pastebin.com/xy4HTyMN . I have not made any intentional changes that I am aware of.

Regarding the discovery process. I believe there is some aspect of cache there. So Android will not do full discovery or any discovery in some cases. I think this depends on time and/or pairing. Might be something to keep in mind when comparing different runs.

mws-rmain commented 6 years ago

@ayavilevich SUCCESS!

I found references online about caching of BLE device info causing problems, and cycling power on the phoneused to clear the cache, but more recent versions of Android very helpfully preserve the cache over power cycles, effectively neutering any possibility of correcting a corrupt cache.

But hope springs eternal, so I just tried power cycling my LG G5. To my amazement, I am NOW ABLE TO SEE ALL ATTRIBUTES!

I am ALSO now able to duplicate your 'multi-connect' scenario, and it does result in a reconnect loop. All disconnections I saw in my log were timeouts (8) (See below).

Oddly, I still see the bogus 'attribute dump' just prior to the connecting message fro my ESP32. This must be some kind of bug in nRF Connect, because there doesn't appear to be any legitimate reason for dumping anything, let alone a mis-mash of attributes from multiple devices. Do you see this at the start of an nRF Connect log?

nRF Connect, 2018-03-22
ESP_GATTS_DEMO (24:0A:C4:07:22:D2)
I   10:20:41.826    [Server] Server started
V   10:20:41.888    Unknown Service (3ab10100-f831-4395-b29d-570977d5bf94)
            - Unknown Characteristic [I R] (3ab10101-f831-4395-b29d-570977d5bf94)
               Client Characteristic Configuration (0x2902)
            - Unknown Characteristic [I R] (3ab10102-f831-4395-b29d-570977d5bf94)
               Client Characteristic Configuration (0x2902)
            - Unknown Characteristic [I R] (3ab10103-f831-4395-b29d-570977d5bf94)
               Client Characteristic Configuration (0x2902)
            - Unknown Characteristic [I R] (3ab10104-f831-4395-b29d-570977d5bf94)
               Client Characteristic Configuration (0x2902)
            - Unknown Characteristic [I R] (3ab10105-f831-4395-b29d-570977d5bf94)
               Client Characteristic Configuration (0x2902)
            - Unknown Characteristic [WNR] (3ab10109-f831-4395-b29d-570977d5bf94)
            - Unknown Characteristic [I R] (3ab1010a-f831-4395-b29d-570977d5bf94)
               Client Characteristic Configuration (0x2902)
            - Unknown Characteristic [R] (3ab1010c-f831-4395-b29d-570977d5bf94)
            Human Interface Device (0x1812)
            - Report [N R] (0x2A4D)
               Report Reference (0x2908)
               Client Characteristic Configuration (0x2902)
            - Report [N R] (0x2A4D)
               Report Reference (0x2908)
               Client Characteristic Configuration (0x2902)
            - HID Information [R] (0x2A4A)
            - Protocol Mode [R WNR] (0x2A4E)
            - HID Control Point [WNR] (0x2A4C)
            - Report Map [R] (0x2A4B)
            - Report [R W WNR] (0x2A4D)
               Report Reference (0x2908)
            - Boot Keyboard Input Report [N R] (0x2A22)
               Client Characteristic Configuration (0x2902)
            - Boot Keyboard Output Report [R W WNR] (0x2A32)
            Battery Service (0x180F)
            - Battery Level [R] (0x2A19)
            - Battery Power State [R] (0x2A1A)
            Scan Parameters (0x1813)
            - Scan Interval Window [WNR] (0x2A4F)
            - Scan Refresh [N] (0x2A31)
               Client Characteristic Configuration (0x2902)
            Device Information (0x180A)
            - PnP ID [R] (0x2A50)
            - Hardware Revision String [R] (0x2A27)
V   10:20:42.213    Connecting to 24:0A:C4:07:22:D2...
D   10:20:42.213    gatt = device.connectGatt(autoConnect = true, TRANSPORT_LE)
D   10:20:45.783    [Server callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I   10:20:45.783    [Server] Device with address 24:0A:C4:07:22:D2 connected
V   10:20:45.783    [Server] Creating server connection...
D   10:20:45.783    server.connect(device, autoConnect = true)
D   10:20:45.796    [Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I   10:20:45.796    Connected to 24:0A:C4:07:22:D2
V   10:20:45.833    Discovering services...
D   10:20:45.833    gatt.discoverServices()
D   10:20:45.836    [Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
D   10:20:45.838    [Callback] Services discovered with status: 0
I   10:20:45.840    Services discovered
V   10:20:45.864    Generic Attribute (0x1801)
            - Service Changed [I] (0x2A05)
            Generic Access (0x1800)
            - Device Name [R] (0x2A00)
            - Appearance [R] (0x2A01)
            - Central Address Resolution [R] (0x2AA6)
            Unknown Service (000000ff-0000-1000-8000-00805f9b34fb)
            - Unknown Characteristic [N R W] (0000ff01-0000-1000-8000-00805f9b34fb)
               Client Characteristic Configuration (0x2902)
            Unknown Service (000000ee-0000-1000-8000-00805f9b34fb)
            - Unknown Characteristic [N R W] (0000ee01-0000-1000-8000-00805f9b34fb)
               Client Characteristic Configuration (0x2902)
D   10:20:50.626    [Server callback] Connection state changed with status: 0 and new state: DISCONNECTED (0)
I   10:20:50.626    [Server] Device disconnected
D   10:20:50.626    [Callback] Connection state changed with status: 8 and new state: DISCONNECTED (0)
E   10:20:50.629    Error 8 (0x8): GATT CONN TIMEOUT
I   10:20:50.629    Disconnected
D   10:20:50.633    [Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
D   10:20:55.769    [Server callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I   10:20:55.769    [Server] Device with address 24:0A:C4:07:22:D2 connected
V   10:20:55.769    [Server] Creating server connection...
D   10:20:55.769    server.connect(device, autoConnect = true)
V   10:20:55.781    Connecting to 24:0A:C4:07:22:D2...
D   10:20:55.781    gatt.connect()
D   10:20:55.786    [Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I   10:20:55.786    Connected to 24:0A:C4:07:22:D2
D   10:20:55.808    [Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
V   10:20:55.808    Discovering services...
D   10:20:55.808    gatt.discoverServices()
D   10:20:55.818    [Callback] Services discovered with status: 0
I   10:20:55.821    Services discovered
V   10:20:55.857    Generic Attribute (0x1801)
            - Service Changed [I] (0x2A05)
            Generic Access (0x1800)
            - Device Name [R] (0x2A00)
            - Appearance [R] (0x2A01)
            - Central Address Resolution [R] (0x2AA6)
            Unknown Service (000000ff-0000-1000-8000-00805f9b34fb)
            - Unknown Characteristic [N R W] (0000ff01-0000-1000-8000-00805f9b34fb)
               Client Characteristic Configuration (0x2902)
            Unknown Service (000000ee-0000-1000-8000-00805f9b34fb)
            - Unknown Characteristic [N R W] (0000ee01-0000-1000-8000-00805f9b34fb)
               Client Characteristic Configuration (0x2902)
D   10:21:00.634    [Server callback] Connection state changed with status: 0 and new state: DISCONNECTED (0)
I   10:21:00.635    [Server] Device disconnected
D   10:21:00.637    [Callback] Connection state changed with status: 8 and new state: DISCONNECTED (0)
E   10:21:00.637    Error 8 (0x8): GATT CONN TIMEOUT
I   10:21:00.637    Disconnected
D   10:21:00.720    [Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
D   10:21:05.764    [Server callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I   10:21:05.764    [Server] Device with address 24:0A:C4:07:22:D2 connected
V   10:21:05.764    [Server] Creating server connection...
D   10:21:05.764    server.connect(device, autoConnect = true)
D   10:21:05.775    [Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I   10:21:05.775    Connected to 24:0A:C4:07:22:D2
V   10:21:05.781    Connecting to 24:0A:C4:07:22:D2...
D   10:21:05.781    gatt.connect()
D   10:21:05.798    [Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
D   10:21:10.658    [Server callback] Connection state changed with status: 0 and new state: DISCONNECTED (0)
I   10:21:10.658    [Server] Device disconnected
D   10:21:10.670    [Callback] Connection state changed with status: 8 and new state: DISCONNECTED (0)
E   10:21:10.670    Error 8 (0x8): GATT CONN TIMEOUT
I   10:21:10.670    Disconnected
D   10:21:10.724    [Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
D   10:21:15.754    [Server callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I   10:21:15.754    [Server] Device with address 24:0A:C4:07:22:D2 connected
V   10:21:15.754    [Server] Creating server connection...
D   10:21:15.754    server.connect(device, autoConnect = true)
D   10:21:15.762    [Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
V   10:21:15.766    Connecting to 24:0A:C4:07:22:D2...
D   10:21:15.766    gatt.connect()
D   10:21:15.767    [Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I   10:21:15.767    Connected to 24:0A:C4:07:22:D2
V   10:21:15.772    Discovering services...
D   10:21:15.772    gatt.discoverServices()
D   10:21:15.777    [Callback] Services discovered with status: 0
I   10:21:15.779    Services discovered
V   10:21:15.795    Generic Attribute (0x1801)
            - Service Changed [I] (0x2A05)
            Generic Access (0x1800)
            - Device Name [R] (0x2A00)
            - Appearance [R] (0x2A01)
            - Central Address Resolution [R] (0x2AA6)
            Unknown Service (000000ff-0000-1000-8000-00805f9b34fb)
            - Unknown Characteristic [N R W] (0000ff01-0000-1000-8000-00805f9b34fb)
               Client Characteristic Configuration (0x2902)
            Unknown Service (000000ee-0000-1000-8000-00805f9b34fb)
            - Unknown Characteristic [N R W] (0000ee01-0000-1000-8000-00805f9b34fb)
               Client Characteristic Configuration (0x2902)
D   10:21:20.665    [Server callback] Connection state changed with status: 0 and new state: DISCONNECTED (0)
I   10:21:20.665    [Server] Device disconnected
D   10:21:20.670    [Callback] Connection state changed with status: 8 and new state: DISCONNECTED (0)
E   10:21:20.671    Error 8 (0x8): GATT CONN TIMEOUT
I   10:21:20.671    Disconnected
D   10:21:20.750    [Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
D   10:21:25.758    [Server callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I   10:21:25.758    [Server] Device with address 24:0A:C4:07:22:D2 connected
V   10:21:25.758    [Server] Creating server connection...
D   10:21:25.758    server.connect(device, autoConnect = true)
D   10:21:25.765    [Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I   10:21:25.765    Connected to 24:0A:C4:07:22:D2
D   10:21:25.771    [Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
V   10:21:25.776    Connecting to 24:0A:C4:07:22:D2...
D   10:21:25.776    gatt.connect()
D   10:21:30.644    [Server callback] Connection state changed with status: 0 and new state: DISCONNECTED (0)
I   10:21:30.644    [Server] Device disconnected
D   10:21:30.646    [Callback] Connection state changed with status: 8 and new state: DISCONNECTED (0)
E   10:21:30.646    Error 8 (0x8): GATT CONN TIMEOUT
I   10:21:30.646    Disconnected
D   10:21:30.720    [Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
D   10:21:35.760    [Server callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I   10:21:35.760    [Server] Device with address 24:0A:C4:07:22:D2 connected
V   10:21:35.760    [Server] Creating server connection...
D   10:21:35.760    server.connect(device, autoConnect = true)
V   10:21:35.768    Connecting to 24:0A:C4:07:22:D2...
D   10:21:35.769    gatt.connect()
D   10:21:35.778    [Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I   10:21:35.778    Connected to 24:0A:C4:07:22:D2
D   10:21:35.787    [Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
V   10:21:35.787    Discovering services...
D   10:21:35.787    gatt.discoverServices()
D   10:21:35.794    [Callback] Services discovered with status: 0
I   10:21:35.797    Services discovered
V   10:21:35.830    Generic Attribute (0x1801)
            - Service Changed [I] (0x2A05)
            Generic Access (0x1800)
            - Device Name [R] (0x2A00)
            - Appearance [R] (0x2A01)
            - Central Address Resolution [R] (0x2AA6)
            Unknown Service (000000ff-0000-1000-8000-00805f9b34fb)
            - Unknown Characteristic [N R W] (0000ff01-0000-1000-8000-00805f9b34fb)
               Client Characteristic Configuration (0x2902)
            Unknown Service (000000ee-0000-1000-8000-00805f9b34fb)
            - Unknown Characteristic [N R W] (0000ee01-0000-1000-8000-00805f9b34fb)
               Client Characteristic Configuration (0x2902)
D   10:21:40.656    [Server callback] Connection state changed with status: 0 and new state: DISCONNECTED (0)
I   10:21:40.656    [Server] Device disconnected
D   10:21:40.658    [Callback] Connection state changed with status: 8 and new state: DISCONNECTED (0)
E   10:21:40.658    Error 8 (0x8): GATT CONN TIMEOUT
I   10:21:40.659    Disconnected
D   10:21:40.686    [Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
D   10:21:45.757    [Server callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I   10:21:45.757    [Server] Device with address 24:0A:C4:07:22:D2 connected
V   10:21:45.757    [Server] Creating server connection...
D   10:21:45.757    server.connect(device, autoConnect = true)
V   10:21:45.767    Connecting to 24:0A:C4:07:22:D2...
D   10:21:45.767    gatt.connect()
D   10:21:45.771    [Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I   10:21:45.771    Connected to 24:0A:C4:07:22:D2
V   10:21:45.785    Discovering services...
D   10:21:45.785    gatt.discoverServices()
D   10:21:45.794    [Callback] Services discovered with status: 0
I   10:21:45.799    Services discovered
V   10:21:45.812    Generic Attribute (0x1801)
            - Service Changed [I] (0x2A05)
            Generic Access (0x1800)
            - Device Name [R] (0x2A00)
            - Appearance [R] (0x2A01)
            - Central Address Resolution [R] (0x2AA6)
            Unknown Service (000000ff-0000-1000-8000-00805f9b34fb)
            - Unknown Characteristic [N R W] (0000ff01-0000-1000-8000-00805f9b34fb)
               Client Characteristic Configuration (0x2902)
            Unknown Service (000000ee-0000-1000-8000-00805f9b34fb)
            - Unknown Characteristic [N R W] (0000ee01-0000-1000-8000-00805f9b34fb)
               Client Characteristic Configuration (0x2902)
D   10:21:50.652    [Server callback] Connection state changed with status: 0 and new state: DISCONNECTED (0)
D   10:21:50.652    [Callback] Connection state changed with status: 8 and new state: DISCONNECTED (0)
I   10:21:50.652    [Server] Device disconnected
E   10:21:50.652    Error 8 (0x8): GATT CONN TIMEOUT
I   10:21:50.652    Disconnected
D   10:21:50.669    [Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
D   10:21:55.750    [Server callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I   10:21:55.750    [Server] Device with address 24:0A:C4:07:22:D2 connected
V   10:21:55.750    [Server] Creating server connection...
D   10:21:55.750    server.connect(device, autoConnect = true)
D   10:21:55.756    [Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I   10:21:55.756    Connected to 24:0A:C4:07:22:D2
V   10:21:55.764    Connecting to 24:0A:C4:07:22:D2...
D   10:21:55.764    gatt.connect()
D   10:21:55.774    [Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
D   10:22:00.628    [Callback] Connection state changed with status: 8 and new state: DISCONNECTED (0)
E   10:22:00.628    Error 8 (0x8): GATT CONN TIMEOUT
I   10:22:00.628    Disconnected
D   10:22:00.628    [Server callback] Connection state changed with status: 0 and new state: DISCONNECTED (0)
I   10:22:00.628    [Server] Device disconnected
D   10:22:00.649    [Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED

I was going to suggest you try:

purging your phone of any 'other' connected bluetooth devices; and
turning OFF WiFi.

However, I captured the log above with both suggestions in place, and it the unexpected disconnections still occured.

mws-rmain commented 6 years ago

@ayavilevich For the record, here are a list of differences in SDKConfig (not that it matters much, since we are both seeing the same behaviour, now).

@ayavilevich SDKConfig

ESPTOOLPY_PORT="COM15" (i.e., windows environment)
OPTIMIZATION_LEVEL_DEBUG=y
SYSTEM_EVENT_TASK_STACK_SIZE=4096
MAIN_TASK_STACK_SIZE=4096
TIMER_TASK_STACK_SIZE=4096
TCPIP_TASK_STACK_SIZE=2560
PTHREAD_TASK_STACK_SIZE_DEFAULT=2048

@mws-rmain

ESPTOOLPY_PORT="/dev/ttyUSB0" (i.e., linux environment - actually linux in a virtual machine on windows)
OPTIMIZATION_LEVEL_RELEASE=y
SYSTEM_EVENT_TASK_STACK_SIZE=2304
MAIN_TASK_STACK_SIZE=3548
TIMER_TASK_STACK_SIZE=3584
TCPIP_TASK_STACK_SIZE=2048
PTHREAD_TASK_STACK_SIZE_DEFAULT=3072

Other than changing the optimization to 'release', I don't believe I made intentional changes - certainly not to the stack sizes, so I'm unsure where these came from.

ayavilevich commented 6 years ago

@mws-rmain AWESOME!! Thanks for spending the time and reproducing the issue.

@Weijian-Espressif hopefully this is something that will reproduce on your end too.

@mws-rmain I am out of the office and will review your report in detail later. Meanwhile, a few questions:

Can you link to some references about the caching issues?
Are the discovery attribute data caching issues only relevant if you change the services/characteristics of your service while developing? Have you been doing that? Because I have mine fixed.
Can you try to reproduce the multi-connect issue on other phones you have? Please specify model and Android OS version.
Why do you think WiFi can affect the results?
What do you mean by "a mis-mash of attributes from multiple devices"?
Did you take a look at my nRF logs at the top of the issue?
Why do you have "[Server] Server started" in your nRF log? This is something I didn't see on my end?

mws-rmain commented 6 years ago

@ayavilevich

Re: caching issues. I came across that quite some time ago, while looking for something else I will take a look.
Re: caching & changed services. I can't be sure at this point, but it is possible my LG G5 has seen services change under the same UUID. If so, this might be the root cause.
I did a quick run with the Pixel 1 (nRF log below). It did NOT show the spurious disconnect issue. I waited several minutes (to ensure any disconnects that might occur had time), then manually disconnected (which you see in the log).
WiFi & Bluetooth (/LE) both occupy the 2.4GHz band. IN THEORY, they co-exist. However, I encountered some really odd behaviour with WiFi on an Android phone some time ago. The issue was never resolved. Android would periodically dissappear 'off channel' when I had an open socket streaming information, and had done everything I could find to lock it down to the operating channel. Of course, when it was off-channel packets were dropped, and lots of fun ensued. I expect the OS was off-channel attempting to scan for alternative access points (the one we had active was a piece of embedded equipment, so it was not usefull as a path to the internet - which Android seemed to want really badly). If you're interested, you can find more here. I thought if Android was doing it's dance looking for alternative WiFi access points, it might stomp on BLE operations. Worth a test, anyway.
Re: mish-mash of attributes - see the dump of a long list of attributes from all of my G5 nRF logs (except the first one, where I deleted them, thinking they were logged during the initial scan for devices). The attributes in the list are NOT all from one device. I don't know why you don't see it in your logs. Do you have allot of BLE devices in your initial scan list?
Re: "[Server] Server started". I don't know why this appears in my logs, but not yours. It appears to be something nRF is logging. I haven't done anything that I know of that might cause it.

nRF Connect, 2018-03-22
ESP_GATTS_DEMO (24:0A:C4:07:22:D2)
V   13:47:16.671    Connecting to 24:0A:C4:07:22:D2...
D   13:47:16.671    gatt = device.connectGatt(autoConnect = true, TRANSPORT_LE, preferred PHY = LE 1M)
D   13:47:17.067    [Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
D   13:47:17.068    [Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I   13:47:17.068    Connected to 24:0A:C4:07:22:D2
V   13:47:17.095    Discovering services...
D   13:47:17.095    gatt.discoverServices()
I   13:47:17.788    Connection parameters updated (interval: 37.5ms, latency: 0, timeout: 4000ms)
I   13:47:18.257    Connection parameters updated (interval: 7.5ms, latency: 0, timeout: 5000ms)
D   13:47:18.412    [Callback] Services discovered with status: 0
I   13:47:18.415    Services discovered
V   13:47:18.437    Generic Attribute (0x1801)
            - Service Changed [I] (0x2A05)
            Generic Access (0x1800)
            - Device Name [R] (0x2A00)
            - Appearance [R] (0x2A01)
            - Central Address Resolution [R] (0x2AA6)
            Unknown Service (000000ff-0000-1000-8000-00805f9b34fb)
            - Unknown Characteristic [N R W] (0000ff01-0000-1000-8000-00805f9b34fb)
               Client Characteristic Configuration (0x2902)
            Unknown Service (000000ee-0000-1000-8000-00805f9b34fb)
            - Unknown Characteristic [N R W] (0000ee01-0000-1000-8000-00805f9b34fb)
               Client Characteristic Configuration (0x2902)
I   13:47:18.486    Connection parameters updated (interval: 37.5ms, latency: 0, timeout: 4000ms)
V   13:49:34.485    Disconnecting...
D   13:49:34.485    gatt.disconnect()
D   13:49:34.492    [Callback] Connection state changed with status: 0 and new state: DISCONNECTED (0)
I   13:49:34.492    Disconnected
D   13:49:35.561    [Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED

negativekelvin commented 6 years ago

Re: caching issues https://punchthrough.com/blog/posts/attribute-caching-in-ble-advantages-and-pitfalls

mws-rmain commented 6 years ago

@negativekelvin Thanks for the link. I provides a much clearer definition of BLE attribute caching than I've encountered to date. The author makes claims about bricking a device (as far as your phone's access to it). He never clearly indicates how this might happen, but I think the clue was: Make sure the handle for the Service Changed characteristic is constant throughout the lifetime of the firmware versions and attribute tables. If the handle for 'Service Changed' has changed, then presumably you'd lose the ability to force rediscovery. Of course, if cycling power of your phone will force a rediscovery anyway, maybe this is the back-door in these 'edge cases'.

The post I recalled is here. This article is possibly more usefull in this context, because they are dealing with Android caching issues encountered by Nordic nRF MCP ('Master Control Panel, now called 'nRF Connect'), though the information here is over 3 years old.

Apparently I mis-remembered that Android preserved the cache over power cycles. On the link above, there is a post by 'Petter Myhre' that states: On Android 4.3 the cache was cleared if you restarted Bluetooth, but this does not happen in 4.4 (and 5). I think this modification was on purpose.

ayavilevich commented 6 years ago

Status update @Weijian-Espressif @EspressifApp :

Though the attribute caching issue described by @mws-rmain is better understood now, the original issue is still unclear and remains open. I am still experiencing the issue with these reproduce instructions.

Make a version of the gatt_server example that calls esp_ble_gap_start_advertising(&adv_params); in ESP_GATTS_CONNECT_EVT to resume advertisement after a first connection. You can grab what I am using from: https://pastebin.com/jLFVPw4L (also prints more debug info)
Have two BLE devices, device A is ESP32 with the above described modified gatt_server code and device B which can also be ESP32 but it doesn't matter.
Do not connect the phone to the devices prior to the test, restart if unsure
Run "nRF Connect" on the phone
If the devices are not in nRF list, power on both devices and scan from nRF so they are in the device list.
Power down device B, while device A is powered on.
autoConnect to device A.
Should connect ok to A.
autoConnect to device B. This should not complete right away and should continue in the background.
You should now have disconnects for device A. I have seen disconnect reasons: 8, 31, 34.

What I experience most often is a disconnect with timeout (reason 8). Other times I would get status=16 on connection parameters update followed by a disconnect with "error unspecified" 31 (0x1F). Less frequently I would get a disconnect with reason 34 (0x22) which is "LMP_TIMEOUT".

The issue was confirmed by @mws-rmain . Appreciated! I have had this issue with: Samsung S4 (Android 5), LG G4 (Android 6) and LG G5 (Android 7).

Still no idea if this is an ESP32 issue or an Android issue. Asking everybody who can do a test to try and reproduce this and then report the results. If posting, please specify Phone model and Android/iOS version.

mws-rmain commented 6 years ago

I'd like to add that the 'spurious disconnect' problem did NOT occur with my Pixel 1 (Android 8.1.0). I did confirm this issue with my LG G5 (Android 7.0).

I've been giving this a fair bit of thought. The fact you are getting 'timeout' errors complicates diagnostics, because almost anything you do will introduce delays which will innevitably affect / agravate / mask the root cause. You could implement diagnostics on the device side, but I expect all you'd see is a sudden disconnect, with no reason given (so no clue as to what is really happening on the host). Using an RF Sniffer would give similar results. I don't see a good way to diagnose this issue.

I'd suggest you check out this link "BLE on Android: Top Tips for the Tricky Bits" (also check the blog link in the details below - lots of good collected info). Note this was published on Sept. 17, 2017, so is still relevant (unlike allot of info online). I'd suggest you pay particular attention to the 'asynchronous, but still synchronous (/sequential)' comment regarding the operation of the BLE stack. I'd refer to this as 'exhibit A'. He gets into other details, like suggesting you flush everything & re-connect if you detect any exceptions, which sounds like moving the auto-connect logic down into userspace. He's suggesting the autoconnect logic has bugs that WILL cause problems, and you should expect & plan for them.

I suspect that the fact you have tasks periodically re-inserted into the BLE queue to attempt connection to device B (which will always timeout), and that this blocks processing of all OTHER tasks in the queue (such as any pending operations for device A). The timeout for device B operations will be a system level timeout. Possibly the timeout for device A operations is at the application (nRF Connect) level? This is the kind of hypothesis you could test IF source for nRF Connect were available. I could suggest you build an Android BLE app that would give you control over diagnostics, and see if you could setup the same scenario.

mainr commented 6 years ago

One more thought. My suspicions on this are leaning toward an android issue / bug. If you have multiple BLE devices (non-esp32, that supports multi-connect), you could verify this is nothing to do with esp-idf by running the same test without involving esp32.

I don't know how common multi-connect support is (?)

ayavilevich commented 6 years ago

@mainr my thoughts exactly. I saw that nRF52 is advertised as able to support multi-connect both ways. Unfortunately I don't have the skill yet to work with it. The relevant example is: https://github.com/mukymuk/nRF5_SDK_14/tree/master/examples/ble_peripheral/experimental/ble_app_multiperipheral

I am not aware of other devices that support this. I have tried with some HM-10-type modules but the issue doesn't reproduce because those modules don't advertise once connected. Those modules use a TI CC254x which is Bluetooth 4.0 and isn't supposed to support more than one connection (of any type) to a peripheral.

Is there anybody in the community who can try nRF52 with the Nordic example for comparison?

Weijian-Espressif commented 6 years ago

sorry, my LG G5 with android 6.0.1 still can not Reproduce this problem.

ayavilevich commented 6 years ago

@Weijian-Espressif thanks for trying.

I will try to reproduce on more phones or with just ESP32 modules and post an update.

Would appreciate if anyone can give this a try and post the results.

FayeY commented 6 years ago

Closing as can't reproduce. Please feel free to reopen if the issue persists and you can supply more details.