Strange device crash on deprovisioning.
This is probably something incredibly stupid, but I have been fighting this problem for a week and don't know where to turn.
I am writing BLE mesh android application that communicates to nordic nRF52 boards, and ran into a strange problem.
1. Provisioning and communication to the device works fine.
2. When I send deprovision request, Samsung phones with android 9.0 crash the device - I do not have any crashes neither on LG phone with android 9.0, nor on Samsung with Android 8.
Here is more details on what is happening:
a) On the application side, deprovisioning process goes normally: application connects, discovers service, request mtu update, signs up to receive notifications, sends deprovisioning pdu, receives response from the device and disconnects)
(partial log from application and HCI snoop log from the phone below)
b) device always gets deprovisioned and sends back confirmation
c) device crashes right after deprovisioning and sending confirmation. Depending on the timing on the application side everything can look well, or it app may receive error status 19 in OnConnectionStateChahge callback (which means device disconnected on its own).
d) sometimes after this happen, and device is provisioned again, it stops responding to any messages - need to manually reset the device several times and also reset bluetooth on the phone before it starts working again
e) when disconnect happens normally, there are the following lines in the HCI snoop log:
"1391","372.947618","controller","host","HCI_EVT","13","Rcvd LE Meta (LE Connection Update Complete)"
"1392","372.951610","controller","host","HCI_EVT","9","Rcvd Command Complete (LE Set Data Length)"
"1393","373.668598","controller","host","HCI_EVT","14","Rcvd LE Meta (LE Data Length Change)"
"1394","373.933681","host","controller","HCI_CMD","7","Sent Disconnect"
"1395","373.939038","controller","host","HCI_EVT","7","Rcvd Command Status (Disconnect)"
"1396","374.148289","controller","host","HCI_EVT","7","Rcvd Disconnect Complete"
f) when device stops responding to messages after the crash, only the complete commands are there, like this:
"1391","372.947618","controller","host","HCI_EVT","13","Rcvd LE Meta (LE Connection Update Complete)"
"1393","373.668598","controller","host","HCI_EVT","14","Rcvd LE Meta (LE Data Length Change)"
"1396","374.148289","controller","host","HCI_EVT","7","Rcvd Disconnect Complete"
Here is the log from the application:
2020-05-22 09:14:21.838 19517-19517/q.ahg.testblemesh I/==ble==: connection state changed, status=0;new state=2
2020-05-22 09:14:23.738 19517-19517/q.ahg.testblemesh I/==ble==: In on service discovered
2020-05-22 09:14:23.741 19517-19517/q.ahg.testblemesh I/==ble==: Service discovered
2020-05-22 09:14:23.759 19517-19517/q.ahg.testblemesh I/==ble==: changed mtu to 69
2020-05-22 09:14:23.782 19517-19517/q.ahg.testblemesh I/==ble==: done descriptor writing, status=0
2020-05-22 09:14:23.782 19517-19517/q.ahg.testblemesh I/==ble==: sending pdu with opcode 32841 to unicast 2
2020-05-22 09:14:23.783 19517-19517/q.ahg.testblemesh I/==ble==: access layer= 8049
2020-05-22 09:14:23.791 19517-19517/q.ahg.testblemesh I/==ble==: sending whole pdu 003D64A14FE78AD82D9007CE7725EBEF621B4E12E8
2020-05-22 09:14:23.794 19517-19517/q.ahg.testblemesh I/==ble==: on characteristics changed
2020-05-22 09:14:23.794 19517-19517/q.ahg.testblemesh I/==ble==: received ack or beacon message
2020-05-22 09:14:23.809 19517-19517/q.ahg.testblemesh I/==ble==: write acknowledged
2020-05-22 09:14:23.809 19517-19517/q.ahg.testblemesh I/==ble==: writing next
2020-05-22 09:14:23.809 19517-19517/q.ahg.testblemesh I/==ble==: done sending, started timing
2020-05-22 09:14:23.820 19517-19517/q.ahg.testblemesh I/==ble==: processing response 003D2C4D5C2F89D5D8BD3051A0FDE25E2A65FAB437
2020-05-22 09:14:23.837 19517-19517/q.ahg.testblemesh I/==ble==: reset: posted disconnect
2020-05-22 09:14:23.850 19517-19517/q.ahg.testblemesh I/==ble==: connection state changed, status=0;new state=0
2020-05-22 09:14:23.872 19517-19517/q.ahg.testblemesh I/==ble==: disconnected
020-05-22 09:14:24.932 19517-19517/q.ahg.testblemesh I/==ble==: updated seq number to 9
Here is HCI snoop log fro the same part:
"1311","368.476505","host","controller","HCI_CMD","29","Sent LE Create Connection"
"1312","368.481124","controller","host","HCI_EVT","7","Rcvd Command Status (LE Create Connection)"
"1313","370.404055","controller","host","HCI_EVT","34","Rcvd LE Meta (LE Enhanced Connection Complete)"
"1314","370.405530","host","controller","HCI_CMD","6","Sent LE Read Remote Features"
"1315","370.407397","controller","host","HCI_EVT","7","Rcvd Command Status (LE Read Remote Features)"
"1316","370.473314","controller","host","HCI_EVT","15","Rcvd LE Meta (LE Read Remote Features Complete)"
"1317","370.474164","host","controller","HCI_CMD","6","Sent Read Remote Version Information"
"1318","370.477437","controller","host","HCI_EVT","7","Rcvd Command Status (Read Remote Version Information)"
"1319","370.517987","ec:17:11:0d:04:20 (nRF5x Mesh Light)","SamsungE_1b:75:df (Galaxy A10e)","L2CAP","21","Rcvd Connection Parameter Update Request"
"1320","370.520504","SamsungE_1b:75:df (Galaxy A10e)","ec:17:11:0d:04:20 (nRF5x Mesh Light)","L2CAP","15","Sent Connection Parameter Update Response (Accepted)"
"1321","370.521237","host","controller","HCI_CMD","18","Sent LE Connection Update"
"1322","370.521892","SamsungE_1b:75:df (Galaxy A10e)","ec:17:11:0d:04:20 (nRF5x Mesh Light)","ATT","16","Sent Read By Group Type Request, GATT Primary Service Declaration, Handles: 0x0001..0xffff"
"1323","370.522955","controller","host","HCI_EVT","7","Rcvd Command Status (LE Connection Update)"
"1324","370.562783","controller","host","HCI_EVT","11","Rcvd Read Remote Version Information Complete"
"1325","370.563465","controller","host","HCI_EVT","7","Rcvd Command Status (No Operation)"
"1326","370.564516","controller","host","HCI_EVT","8","Rcvd Number of Completed Packets"
"1327","370.607636","controller","host","HCI_EVT","8","Rcvd Number of Completed Packets"
"1328","370.653035","ec:17:11:0d:04:20 (nRF5x Mesh Light)","SamsungE_1b:75:df (Galaxy A10e)","ATT","29","Rcvd Read By Group Type Response, Attribute List Length: 3, Generic Access Profile, Generic Attribute Profile, Mesh Proxy Service"
"1329","370.654080","SamsungE_1b:75:df (Galaxy A10e)","ec:17:11:0d:04:20 (nRF5x Mesh Light)","ATT","16","Sent Read By Type Request, GATT Include Declaration, Handles: 0x0001..0x0009"
"1330","370.697776","controller","host","HCI_EVT","8","Rcvd Number of Completed Packets"
"1331","370.742896","ec:17:11:0d:04:20 (nRF5x Mesh Light)","SamsungE_1b:75:df (Galaxy A10e)","ATT","14","Rcvd Error Response - Attribute Not Found, Handle: 0x0001 (Generic Access Profile)"
"1332","370.743581","SamsungE_1b:75:df (Galaxy A10e)","ec:17:11:0d:04:20 (nRF5x Mesh Light)","ATT","16","Sent Read By Type Request, GATT Characteristic Declaration, Handles: 0x0001..0x0009"
"1333","370.787681","controller","host","HCI_EVT","8","Rcvd Number of Completed Packets"
"1334","370.832908","ec:17:11:0d:04:20 (nRF5x Mesh Light)","SamsungE_1b:75:df (Galaxy A10e)","ATT","32","Rcvd Read By Type Response, Attribute List Length: 3, Device Name, Appearance, Peripheral Preferred Connection Parameters"
"1335","370.833408","SamsungE_1b:75:df (Galaxy A10e)","ec:17:11:0d:04:20 (nRF5x Mesh Light)","ATT","16","Sent Read By Type Request, GATT Characteristic Declaration, Handles: 0x0007..0x0009"
"1336","370.878344","controller","host","HCI_EVT","8","Rcvd Number of Completed Packets"
"1337","370.924029","ec:17:11:0d:04:20 (nRF5x Mesh Light)","SamsungE_1b:75:df (Galaxy A10e)","ATT","18","Rcvd Read By Type Response, Attribute List Length: 1, Central Address Resolution"
"1338","370.925122","SamsungE_1b:75:df (Galaxy A10e)","ec:17:11:0d:04:20 (nRF5x Mesh Light)","ATT","16","Sent Read By Type Request, GATT Characteristic Declaration, Handles: 0x0009..0x0009"
"1339","370.968625","controller","host","HCI_EVT","8","Rcvd Number of Completed Packets"
"1340","371.012976","controller","host","HCI_EVT","13","Rcvd LE Meta (LE Connection Update Complete)"
"1341","371.026835","host","controller","HCI_CMD","18","Sent LE Connection Update"
"1342","371.028731","ec:17:11:0d:04:20 (nRF5x Mesh Light)","SamsungE_1b:75:df (Galaxy A10e)","ATT","14","Rcvd Error Response - Attribute Not Found, Handle: 0x0009 (Generic Access Profile: Central Address Resolution)"
"1343","371.030309","controller","host","HCI_EVT","7","Rcvd Command Status (LE Connection Update)"
"1344","371.030928","SamsungE_1b:75:df (Galaxy A10e)","ec:17:11:0d:04:20 (nRF5x Mesh Light)","ATT","16","Sent Read By Type Request, GATT Include Declaration, Handles: 0x000a..0x000d"
"1345","371.508862","controller","host","HCI_EVT","8","Rcvd Number of Completed Packets"
"1346","371.748582","ec:17:11:0d:04:20 (nRF5x Mesh Light)","SamsungE_1b:75:df (Galaxy A10e)","ATT","14","Rcvd Error Response - Attribute Not Found, Handle: 0x000a (Generic Attribute Profile)"
"1347","371.750163","SamsungE_1b:75:df (Galaxy A10e)","ec:17:11:0d:04:20 (nRF5x Mesh Light)","ATT","16","Sent Read By Type Request, GATT Characteristic Declaration, Handles: 0x000a..0x000d"
"1348","371.988870","controller","host","HCI_EVT","8","Rcvd Number of Completed Packets"
"1349","372.229045","ec:17:11:0d:04:20 (nRF5x Mesh Light)","SamsungE_1b:75:df (Galaxy A10e)","ATT","18","Rcvd Read By Type Response, Attribute List Length: 1, Service Changed"
"1350","372.230013","SamsungE_1b:75:df (Galaxy A10e)","ec:17:11:0d:04:20 (nRF5x Mesh Light)","ATT","16","Sent Read By Type Request, GATT Characteristic Declaration, Handles: 0x000c..0x000d"
"1351","372.468850","controller","host","HCI_EVT","8","Rcvd Number of Completed Packets"
"1352","372.707251","controller","host","HCI_EVT","13","Rcvd LE Meta (LE Connection Update Complete)"
"1353","372.708863","ec:17:11:0d:04:20 (nRF5x Mesh Light)","SamsungE_1b:75:df (Galaxy A10e)","ATT","14","Rcvd Error Response - Attribute Not Found, Handle: 0x000c (Generic Attribute Profile: Service Changed)"
"1354","372.710330","SamsungE_1b:75:df (Galaxy A10e)","ec:17:11:0d:04:20 (nRF5x Mesh Light)","ATT","14","Sent Find Information Request, Handles: 0x000d..0x000d"
"1355","372.716078","ec:17:11:0d:04:20 (nRF5x Mesh Light)","SamsungE_1b:75:df (Galaxy A10e)","L2CAP","21","Rcvd Connection Parameter Update Request"
"1356","372.716903","SamsungE_1b:75:df (Galaxy A10e)","ec:17:11:0d:04:20 (nRF5x Mesh Light)","L2CAP","15","Sent Connection Parameter Update Response (Accepted)"
"1357","372.717804","controller","host","HCI_EVT","8","Rcvd Number of Completed Packets"
"1358","372.723656","ec:17:11:0d:04:20 (nRF5x Mesh Light)","SamsungE_1b:75:df (Galaxy A10e)","ATT","15","Rcvd Find Information Response, Handle: 0x000d (Generic Attribute Profile: Service Changed: Client Characteristic Configuration)"
"1359","372.725239","SamsungE_1b:75:df (Galaxy A10e)","ec:17:11:0d:04:20 (nRF5x Mesh Light)","ATT","16","Sent Read By Type Request, GATT Include Declaration, Handles: 0x000e..0xffff"
"1360","372.725520","controller","host","HCI_EVT","8","Rcvd Number of Completed Packets"
"1361","372.731155","controller","host","HCI_EVT","8","Rcvd Number of Completed Packets"
"1362","372.738616","ec:17:11:0d:04:20 (nRF5x Mesh Light)","SamsungE_1b:75:df (Galaxy A10e)","ATT","14","Rcvd Error Response - Attribute Not Found, Handle: 0x000e (Mesh Proxy Service)"
"1363","372.739967","SamsungE_1b:75:df (Galaxy A10e)","ec:17:11:0d:04:20 (nRF5x Mesh Light)","ATT","16","Sent Read By Type Request, GATT Characteristic Declaration, Handles: 0x000e..0xffff"
"1364","372.745900","controller","host","HCI_EVT","8","Rcvd Number of Completed Packets"
"1365","372.753008","ec:17:11:0d:04:20 (nRF5x Mesh Light)","SamsungE_1b:75:df (Galaxy A10e)","ATT","25","Rcvd Read By Type Response, Attribute List Length: 2, Mesh Proxy Data In, Mesh Proxy Data Out"
"1366","372.753504","SamsungE_1b:75:df (Galaxy A10e)","ec:17:11:0d:04:20 (nRF5x Mesh Light)","ATT","16","Sent Read By Type Request, GATT Characteristic Declaration, Handles: 0x0012..0xffff"
"1367","372.760571","controller","host","HCI_EVT","8","Rcvd Number of Completed Packets"
"1368","372.768031","ec:17:11:0d:04:20 (nRF5x Mesh Light)","SamsungE_1b:75:df (Galaxy A10e)","ATT","14","Rcvd Error Response - Attribute Not Found, Handle: 0x0012 (Mesh Proxy Service: Mesh Proxy Data Out)"
"1369","372.769023","SamsungE_1b:75:df (Galaxy A10e)","ec:17:11:0d:04:20 (nRF5x Mesh Light)","ATT","14","Sent Find Information Request, Handles: 0x0013..0xffff"
"1370","372.775471","controller","host","HCI_EVT","8","Rcvd Number of Completed Packets"
"1371","372.783066","ec:17:11:0d:04:20 (nRF5x Mesh Light)","SamsungE_1b:75:df (Galaxy A10e)","ATT","15","Rcvd Find Information Response, Handle: 0x0013 (Mesh Proxy Service: Mesh Proxy Data Out: Client Characteristic Configuration)"
"1372","372.783597","SamsungE_1b:75:df (Galaxy A10e)","ec:17:11:0d:04:20 (nRF5x Mesh Light)","ATT","14","Sent Find Information Request, Handles: 0x0014..0xffff"
"1373","372.790426","controller","host","HCI_EVT","8","Rcvd Number of Completed Packets"
"1374","372.798065","ec:17:11:0d:04:20 (nRF5x Mesh Light)","SamsungE_1b:75:df (Galaxy A10e)","ATT","14","Rcvd Error Response - Attribute Not Found, Handle: 0x0014 (Mesh Proxy Service: Mesh Proxy Data Out: Unknown)"
"1375","372.798933","host","controller","HCI_CMD","18","Sent LE Connection Update"
"1376","372.800014","controller","host","HCI_EVT","7","Rcvd Command Status (LE Connection Update)"
"1377","372.814671","SamsungE_1b:75:df (Galaxy A10e)","ec:17:11:0d:04:20 (nRF5x Mesh Light)","ATT","12","Sent Exchange MTU Request, Client Rx MTU: 503"
"1378","372.820963","controller","host","HCI_EVT","8","Rcvd Number of Completed Packets"
"1379","372.828866","ec:17:11:0d:04:20 (nRF5x Mesh Light)","SamsungE_1b:75:df (Galaxy A10e)","ATT","12","Rcvd Exchange MTU Response, Server Rx MTU: 69"
"1380","372.829690","host","controller","HCI_CMD","10","Sent LE Set Data Length"
"1381","372.831431","controller","host","HCI_EVT","9","Rcvd Command Complete (LE Set Data Length)"
"1382","372.840987","SamsungE_1b:75:df (Galaxy A10e)","ec:17:11:0d:04:20 (nRF5x Mesh Light)","ATT","14","Sent Write Request, Handle: 0x0013 (Mesh Proxy Service: Mesh Proxy Data Out: Client Characteristic Configuration)"
"1383","372.853236","controller","host","HCI_EVT","8","Rcvd Number of Completed Packets"
"1384","372.858169","ec:17:11:0d:04:20 (nRF5x Mesh Light)","SamsungE_1b:75:df (Galaxy A10e)","ATT","10","Rcvd Write Response, Handle: 0x0013 (Mesh Proxy Service: Mesh Proxy Data Out: Client Characteristic Configuration)"
"1385","372.859595","ec:17:11:0d:04:20 (nRF5x Mesh Light)","SamsungE_1b:75:df (Galaxy A10e)","HCI_ACL","32","Rcvd [Reassembled in #1386]"
"1386","372.861265","ec:17:11:0d:04:20 (nRF5x Mesh Light)","SamsungE_1b:75:df (Galaxy A10e)","BT Mesh Beacon","8","Secure Network Beacon"
"1387","372.888622","SamsungE_1b:75:df (Galaxy A10e)","ec:17:11:0d:04:20 (nRF5x Mesh Light)","BT Mesh","34",""
"1388","372.896046","controller","host","HCI_EVT","8","Rcvd Number of Completed Packets"
"1389","372.910351","ec:17:11:0d:04:20 (nRF5x Mesh Light)","SamsungE_1b:75:df (Galaxy A10e)","HCI_ACL","32","Rcvd [Reassembled in #1390]"
"1390","372.911108","ec:17:11:0d:04:20 (nRF5x Mesh Light)","SamsungE_1b:75:df (Galaxy A10e)","BT Mesh","7",""
"1391","372.947618","controller","host","HCI_EVT","13","Rcvd LE Meta (LE Connection Update Complete)"
"1392","372.951610","controller","host","HCI_EVT","9","Rcvd Command Complete (LE Set Data Length)"
"1393","373.668598","controller","host","HCI_EVT","14","Rcvd LE Meta (LE Data Length Change)"
"1394","373.933681","host","controller","HCI_CMD","7","Sent Disconnect"
"1395","373.939038","controller","host","HCI_EVT","7","Rcvd Command Status (Disconnect)"
"1396","374.148289","controller","host","HCI_EVT","7","Rcvd Disconnect Complete"
Any help and pointers will be sincerely appreciated!
