search

espressif / esp-idf

Espressif IoT Development Framework. Official development framework for Espressif SoCs.
Apache License 2.0
13.51k stars 7.26k forks source link

[TW#17014] BT: Memory leak when using encrypted connections #1381

Closed rojer closed 6 years ago

rojer commented 6 years ago

Enabling encryption on a BT connection leaks memory on every connection. If we add printing free heap to examples/bluetooth/gatt_server and examples/bluetooth/gatt_security_server and compare free memory at each connection, we see the number going down in gatt_security_server but not gatt_server.

Latest IDF (as of today), no changes other than adding printing xPortGetFreeHeapSize() on every ESP_GATTS_CONNECT_EVT (last number).

[Dec 13 17:23:13.319] I (9379) GATTS_DEMO: ESP_GATTS_CONNECT_EVT, conn_id 0, remote 5f:d6:41:b7:9f:ac: ram 167652
[Dec 13 17:23:13.345] I (9379) GATTS_DEMO: CONNECT_EVT, conn_id 0, remote 5f:d6:41:b7:9f:ac:
[Dec 13 17:23:14.144] I (10199) GATTS_DEMO: update connetion params status = 0, min_int = 16, max_int = 32,conn_int = 30,latency = 0, timeout = 400
[Dec 13 17:23:14.888] I (10919) GATTS_DEMO: update connetion params status = 0, min_int = 0, max_int = 0,conn_int = 6,latency = 0, timeout = 500
[Dec 13 17:23:15.080] I (11139) GATTS_DEMO: update connetion params status = 0, min_int = 0, max_int = 0,conn_int = 30,latency = 0, timeout = 400
[Dec 13 17:23:18.262] I (14299) GATTS_DEMO: update connetion params status = 0, min_int = 0, max_int = 0,conn_int = 6,latency = 0, timeout = 500
[Dec 13 17:23:18.342] I (14399) GATTS_DEMO: update connetion params status = 0, min_int = 0, max_int = 0,conn_int = 30,latency = 0, timeout = 400
[Dec 13 17:23:18.874] I (14929) GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT
[Dec 13 17:23:22.620] I (18649) GATTS_DEMO: ESP_GATTS_CONNECT_EVT, conn_id 0, remote 5f:d6:41:b7:9f:ac: ram 167548
[Dec 13 17:23:22.620] I (18649) GATTS_DEMO: CONNECT_EVT, conn_id 0, remote 5f:d6:41:b7:9f:ac:
[Dec 13 17:23:23.370] I (19429) GATTS_DEMO: update connetion params status = 0, min_int = 16, max_int = 32,conn_int = 30,latency = 0, timeout = 400
[Dec 13 17:23:23.851] I (19889) GATTS_DEMO: update connetion params status = 0, min_int = 0, max_int = 0,conn_int = 6,latency = 0, timeout = 500
[Dec 13 17:23:24.042] I (20099) GATTS_DEMO: update connetion params status = 0, min_int = 0, max_int = 0,conn_int = 30,latency = 0, timeout = 400
[Dec 13 17:23:27.274] I (23329) GATTS_DEMO: update connetion params status = 0, min_int = 0, max_int = 0,conn_int = 6,latency = 0, timeout = 500
[Dec 13 17:23:27.379] I (23439) GATTS_DEMO: update connetion params status = 0, min_int = 0, max_int = 0,conn_int = 30,latency = 0, timeout = 400
[Dec 13 17:23:27.869] I (23929) GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT
[Dec 13 17:23:32.804] I (28859) GATTS_DEMO: ESP_GATTS_CONNECT_EVT, conn_id 0, remote 5f:d6:41:b7:9f:ac: ram 167548
[Dec 13 17:23:32.830] I (28859) GATTS_DEMO: CONNECT_EVT, conn_id 0, remote 5f:d6:41:b7:9f:ac:
[Dec 13 17:23:33.533] I (29589) GATTS_DEMO: update connetion params status = 0, min_int = 16, max_int = 32,conn_int = 30,latency = 0, timeout = 400
[Dec 13 17:23:34.276] I (30309) GATTS_DEMO: update connetion params status = 0, min_int = 0, max_int = 0,conn_int = 6,latency = 0, timeout = 500
[Dec 13 17:23:34.468] I (30529) GATTS_DEMO: update connetion params status = 0, min_int = 0, max_int = 0,conn_int = 30,latency = 0, timeout = 400
[Dec 13 17:23:37.028] I (33079) GATTS_DEMO: update connetion params status = 0, min_int = 0, max_int = 0,conn_int = 6,latency = 0, timeout = 500
[Dec 13 17:23:37.129] I (33189) GATTS_DEMO: update connetion params status = 0, min_int = 0, max_int = 0,conn_int = 30,latency = 0, timeout = 400
[Dec 13 17:23:37.666] I (33719) GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT
[Dec 13 17:23:40.710] I (36739) GATTS_DEMO: ESP_GATTS_CONNECT_EVT, conn_id 0, remote 5f:d6:41:b7:9f:ac: ram 167548
[Dec 13 17:23:40.710] I (36739) GATTS_DEMO: CONNECT_EVT, conn_id 0, remote 5f:d6:41:b7:9f:ac:
[Dec 13 17:23:41.507] I (37539) GATTS_DEMO: update connetion params status = 0, min_int = 16, max_int = 32,conn_int = 30,latency = 0, timeout = 400
[Dec 13 17:23:42.225] I (38259) GATTS_DEMO: update connetion params status = 0, min_int = 0, max_int = 0,conn_int = 6,latency = 0, timeout = 500
[Dec 13 17:23:42.417] I (38479) GATTS_DEMO: update connetion params status = 0, min_int = 0, max_int = 0,conn_int = 30,latency = 0, timeout = 400
[Dec 13 17:28:50.291] I (418) SEC_GATTS_DEMO: app_main init bluetooth
[Dec 13 17:28:50.334] I (458) SEC_GATTS_DEMO: The number handle = 8
[Dec 13 17:28:50.334] I (468) SEC_GATTS_DEMO: advertising start success
[Dec 13 17:28:59.480] I (9608) SEC_GATTS_DEMO: ESP_GATTS_CONNECT_EVT ram 168500
[Dec 13 17:28:59.960] I (10108) SEC_GATTS_DEMO: remote BD_ADDR: 5fd641b79fac
[Dec 13 17:29:00.002] I (10108) SEC_GATTS_DEMO: address type = 1
[Dec 13 17:29:00.002] I (10108) SEC_GATTS_DEMO: pair status = success
[Dec 13 17:29:00.002] I (10108) SEC_GATTS_DEMO: Bonded devices number : 1
[Dec 13 17:29:00.002] 
[Dec 13 17:29:00.002] I (10118) SEC_GATTS_DEMO: Bonded devices list : 1
[Dec 13 17:29:00.002] 
[Dec 13 17:29:00.002] I (10118) SEC_GATTS_DEMO: 5f d6 41 b7 9f ac 
[Dec 13 17:29:04.661] I (14788) SEC_GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT
[Dec 13 17:29:04.661] I (14788) SEC_GATTS_DEMO: advertising start success
[Dec 13 17:29:07.200] I (17348) SEC_GATTS_DEMO: ESP_GATTS_CONNECT_EVT ram 168020
[Dec 13 17:29:07.652] I (17798) SEC_GATTS_DEMO: remote BD_ADDR: 5fd641b79fac
[Dec 13 17:29:07.694] I (17798) SEC_GATTS_DEMO: address type = 1
[Dec 13 17:29:07.694] I (17798) SEC_GATTS_DEMO: pair status = success
[Dec 13 17:29:07.694] I (17808) SEC_GATTS_DEMO: Bonded devices number : 1
[Dec 13 17:29:07.695] 
[Dec 13 17:29:07.695] I (17808) SEC_GATTS_DEMO: Bonded devices list : 1
[Dec 13 17:29:07.695] 
[Dec 13 17:29:07.695] I (17818) SEC_GATTS_DEMO: 5f d6 41 b7 9f ac 
[Dec 13 17:29:11.591] I (21718) SEC_GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT
[Dec 13 17:29:11.591] I (21718) SEC_GATTS_DEMO: advertising start success
[Dec 13 17:29:12.621] I (22748) SEC_GATTS_DEMO: ESP_GATTS_CONNECT_EVT ram 167720
[Dec 13 17:29:13.100] I (23248) SEC_GATTS_DEMO: remote BD_ADDR: 5fd641b79fac
[Dec 13 17:29:13.142] I (23248) SEC_GATTS_DEMO: address type = 1
[Dec 13 17:29:13.142] I (23248) SEC_GATTS_DEMO: pair status = success
[Dec 13 17:29:13.143] I (23248) SEC_GATTS_DEMO: Bonded devices number : 1
[Dec 13 17:29:13.143] 
[Dec 13 17:29:13.143] I (23258) SEC_GATTS_DEMO: Bonded devices list : 1
[Dec 13 17:29:13.143] 
[Dec 13 17:29:13.143] I (23258) SEC_GATTS_DEMO: 5f d6 41 b7 9f ac 
[Dec 13 17:29:16.766] I (26888) SEC_GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT
[Dec 13 17:29:16.766] I (26888) SEC_GATTS_DEMO: advertising start success
[Dec 13 17:29:18.139] I (28288) SEC_GATTS_DEMO: ESP_GATTS_CONNECT_EVT ram 167404
[Dec 13 17:29:18.635] I (28778) SEC_GATTS_DEMO: remote BD_ADDR: 5fd641b79fac
[Dec 13 17:29:18.677] I (28778) SEC_GATTS_DEMO: address type = 1
[Dec 13 17:29:18.677] I (28778) SEC_GATTS_DEMO: pair status = success
[Dec 13 17:29:18.677] I (28788) SEC_GATTS_DEMO: Bonded devices number : 1
[Dec 13 17:29:18.677] 
[Dec 13 17:29:18.677] I (28788) SEC_GATTS_DEMO: Bonded devices list : 1
[Dec 13 17:29:18.677] 
[Dec 13 17:29:18.677] I (28798) SEC_GATTS_DEMO: 5f d6 41 b7 9f ac 
[Dec 13 17:29:22.301] I (32428) SEC_GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT
[Dec 13 17:29:22.301] I (32428) SEC_GATTS_DEMO: advertising start success
[Dec 13 17:29:23.061] I (33188) SEC_GATTS_DEMO: ESP_GATTS_CONNECT_EVT ram 167100
[Dec 13 17:29:23.492] I (33638) SEC_GATTS_DEMO: remote BD_ADDR: 5fd641b79fac
[Dec 13 17:29:23.534] I (33638) SEC_GATTS_DEMO: address type = 1
[Dec 13 17:29:23.534] I (33638) SEC_GATTS_DEMO: pair status = success
[Dec 13 17:29:23.534] I (33648) SEC_GATTS_DEMO: Bonded devices number : 1
[Dec 13 17:29:23.534] 
[Dec 13 17:29:23.534] I (33648) SEC_GATTS_DEMO: Bonded devices list : 1
[Dec 13 17:29:23.534] 
[Dec 13 17:29:23.534] I (33658) SEC_GATTS_DEMO: 5f d6 41 b7 9f ac 
[Dec 13 17:29:26.711] I (36838) SEC_GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT
[Dec 13 17:29:26.711] I (36838) SEC_GATTS_DEMO: advertising start success
Yulong-espressif commented 6 years ago

@rojer I think we have fix this issue in the new version of SDK. And I has test it in my version(8f874aaa), there is no memery leak now. Thank you very much.

Yulong-espressif commented 6 years ago

I (48056) SEC_GATTS_DEMO: ESP_GATTS_CONNECT_EVT
I (49886) SEC_GATTS_DEMO: key type = ESP_LE_KEY_LENC
I (49886) SEC_GATTS_DEMO: key type = ESP_LE_KEY_LID
I (50076) SEC_GATTS_DEMO: key type = ESP_LE_KEY_PENC I (50076) SEC_GATTS_DEMO: key type = ESP_LE_KEY_PID I (50076) SEC_GATTS_DEMO: remote BD_ADDR: 46ef75686dc3 I (50076) SEC_GATTS_DEMO: address type = 1 I (50086) SEC_GATTS_DEMO: pair status = success I (50096) SEC_GATTS_DEMO: Bonded devices number : 2

I (50096) SEC_GATTS_DEMO: Bonded devices list : 2

I (50106) SEC_GATTS_DEMO: 46 ef 75 68 6d c3 I (50106) SEC_GATTS_DEMO: 74 b7 b1 4a ff 40 I (60806) SEC_GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT, heap_size = 152388 I (60806) SEC_GATTS_DEMO: advertising start success I (66606) SEC_GATTS_DEMO: ESP_GATTS_CONNECT_EVT I (80556) SEC_GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT, heap_size = 152388 I (80556) SEC_GATTS_DEMO: advertising start success I (101876) SEC_GATTS_DEMO: ESP_GATTS_CONNECT_EVT I (112626) SEC_GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT, heap_size = 152388 I (112626) SEC_GATTS_DEMO: advertising start success I (116926) SEC_GATTS_DEMO: ESP_GATTS_CONNECT_EVT I (138416) SEC_GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT, heap_size = 152388 I (138416) SEC_GATTS_DEMO: advertising start success I (145636) SEC_GATTS_DEMO: ESP_GATTS_CONNECT_EVT I (151516) SEC_GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT, heap_size = 152388 I (151516) SEC_GATTS_DEMO: advertising start success I (155506) SEC_GATTS_DEMO: ESP_GATTS_CONNECT_EVT I (162106) SEC_GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT, heap_size = 152388 I (162116) SEC_GATTS_DEMO: advertising start success

rojer commented 6 years ago

synced to latest master and still seeing the same behavior:

$ git diff
diff --git a/examples/bluetooth/gatt_security_server/main/example_ble_sec_gatts_demo.c b/examples/bluetooth/gatt_security_server/main/example_ble_sec_gatts_demo.c
index eb328c4..9dd9850 100644
--- a/examples/bluetooth/gatt_security_server/main/example_ble_sec_gatts_demo.c
+++ b/examples/bluetooth/gatt_security_server/main/example_ble_sec_gatts_demo.c
@@ -394,7 +394,7 @@ static void gatts_profile_event_handler(esp_gatts_cb_event_t event,
         case ESP_GATTS_STOP_EVT:
             break;
         case ESP_GATTS_CONNECT_EVT:
-            ESP_LOGI(GATTS_TABLE_TAG, "ESP_GATTS_CONNECT_EVT");
+            ESP_LOGI(GATTS_TABLE_TAG, "ESP_GATTS_CONNECT_EVT %d", xPortGetFreeHeapSize());
             /* start security connect with peer device when receive the connect event sent by the master */
             esp_ble_set_encryption(param->connect.remote_bda, ESP_BLE_SEC_ENCRYPT_MITM);
             break;
[Dec 18 11:56:30.613] I (104) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
[Dec 18 11:56:30.882] I (374) phy: phy_version: 366.0, ba9923d, Oct 31 2017, 18:06:17, 0, 0
[Dec 18 11:56:30.882] I (374) SEC_GATTS_DEMO: app_main init bluetooth
[Dec 18 11:56:30.924] I (424) SEC_GATTS_DEMO: The number handle = 8
[Dec 18 11:56:30.932] I (424) SEC_GATTS_DEMO: advertising start success
[Dec 18 11:56:44.361] I (13854) SEC_GATTS_DEMO: ESP_GATTS_CONNECT_EVT 168608
[Dec 18 11:56:44.829] I (14304) SEC_GATTS_DEMO: remote BD_ADDR: 7c66d4970b2b
[Dec 18 11:56:44.829] I (14304) SEC_GATTS_DEMO: address type = 1
[Dec 18 11:56:44.829] I (14304) SEC_GATTS_DEMO: pair status = success
[Dec 18 11:56:44.829] I (14314) SEC_GATTS_DEMO: Bonded devices number : 1
[Dec 18 11:56:44.829] 
[Dec 18 11:56:44.829] I (14314) SEC_GATTS_DEMO: Bonded devices list : 1
[Dec 18 11:56:44.838] 
[Dec 18 11:56:44.838] I (14324) SEC_GATTS_DEMO: 7c 66 d4 97 0b 2b 
[Dec 18 11:56:49.903] I (19394) SEC_GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT
[Dec 18 11:56:49.903] I (19394) SEC_GATTS_DEMO: advertising start success
[Dec 18 11:56:52.282] I (21774) SEC_GATTS_DEMO: ESP_GATTS_CONNECT_EVT 168132
[Dec 18 11:56:52.749] I (22224) SEC_GATTS_DEMO: remote BD_ADDR: 7c66d4970b2b
[Dec 18 11:56:52.750] I (22224) SEC_GATTS_DEMO: address type = 1
[Dec 18 11:56:52.750] I (22224) SEC_GATTS_DEMO: pair status = success
[Dec 18 11:56:52.750] I (22234) SEC_GATTS_DEMO: Bonded devices number : 1
[Dec 18 11:56:52.750] 
[Dec 18 11:56:52.750] I (22234) SEC_GATTS_DEMO: Bonded devices list : 1
[Dec 18 11:56:52.759] 
[Dec 18 11:56:52.759] I (22244) SEC_GATTS_DEMO: 7c 66 d4 97 0b 2b 
[Dec 18 11:56:57.058] I (26544) SEC_GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT
[Dec 18 11:56:57.058] I (26544) SEC_GATTS_DEMO: advertising start success
[Dec 18 11:56:58.133] I (27624) SEC_GATTS_DEMO: ESP_GATTS_CONNECT_EVT 167820
[Dec 18 11:56:58.645] I (28124) SEC_GATTS_DEMO: remote BD_ADDR: 7c66d4970b2b
[Dec 18 11:56:58.646] I (28124) SEC_GATTS_DEMO: address type = 1
[Dec 18 11:56:58.646] I (28124) SEC_GATTS_DEMO: pair status = success
[Dec 18 11:56:58.646] I (28124) SEC_GATTS_DEMO: Bonded devices number : 1
[Dec 18 11:56:58.646] 
[Dec 18 11:56:58.646] I (28134) SEC_GATTS_DEMO: Bonded devices list : 1
[Dec 18 11:56:58.655] 
[Dec 18 11:56:58.655] I (28134) SEC_GATTS_DEMO: 7c 66 d4 97 0b 2b 
[Dec 18 11:57:04.439] I (33924) SEC_GATTS_DEMO: ESP_GATTS_DISCONNECT_EVT
[Dec 18 11:57:04.439] I (33924) SEC_GATTS_DEMO: advertising start success
[Dec 18 11:57:04.705] I (34194) SEC_GATTS_DEMO: ESP_GATTS_CONNECT_EVT 167512
[Dec 18 11:57:05.217] I (34694) SEC_GATTS_DEMO: remote BD_ADDR: 7c66d4970b2b
[Dec 18 11:57:05.217] I (34694) SEC_GATTS_DEMO: address type = 1
[Dec 18 11:57:05.217] I (34694) SEC_GATTS_DEMO: pair status = success
[Dec 18 11:57:05.217] I (34694) SEC_GATTS_DEMO: Bonded devices number : 1
[Dec 18 11:57:05.217] 
[Dec 18 11:57:05.217] I (34704) SEC_GATTS_DEMO: Bonded devices list : 1
[Dec 18 11:57:05.226] 
[Dec 18 11:57:05.226] I (34704) SEC_GATTS_DEMO: 7c 66 d4 97 0b 2b
Yulong-espressif commented 6 years ago

@rojer Ok, thank you very much. We will test again and response to you as soon as posible.

Yulong-espressif commented 6 years ago

@rojer We have find the issues now, we will update it to the new version of SDK soon. Thanks again.

FayeY commented 6 years ago

Hi @rojer , this issue should have been solved in the latest IDF, please have a try, and feel free to reopen if it is still unsolved. Thanks.

rojer commented 6 years ago

tested, can confirm that the bug has been fixed. thanks!