search

shmuelzon / esp32-ble2mqtt

A BLE to MQTT bridge running on an ESP32
MIT License
668 stars 108 forks source link

Queued and dequeued operations mismatch #32

Closed bilogic closed 5 years ago

bilogic commented 5 years ago

Hi,

  1. I'm trying to troubleshoot indications callback and have added an id field to struct operation.
  2. I used a global static queue_id which is incremented inside ble_operation_enqueue()
  3. Notice how the characteristics don't match up in the Enqueue vs Dequeue
W (23350) BLE: Enqueue: id: 2, type: 0, device: 28:fd:80:07:b5:25, char: 00002a01-0000-1000-8000-00805f9b34fb, len: 0, val: 0x0

vs

W (24700) BLE: Dequeue: id: 2, type: 0, device: 28:fd:80:07:b5:25, char: 00002a00-0000-1000-8000-00805f9b34fb, len: 0, val: 0x0

Could you verify this at your end? Thank you.

Full logs:

D (17220) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (17320) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (17430) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (17530) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (17530) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (18940) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (20780) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (21700) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (21800) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (21810) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (21910) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
I (21910) BLE2MQTT: Discovered BLE device: 28:fd:80:07:b5:25, connecting
D (21920) BLE: Received GAP event 18 (ESP_GAP_BLE_SCAN_STOP_COMPLETE_EVT)
W (22120) BLE: Received GATTC event 40 (ESP_GATTC_CONNECT_EVT), gattc_if 1
W (22120) BLE: GATTC event 40 wasn't handled
W (22120) BLE: Received GATTC event 2 (ESP_GATTC_OPEN_EVT), gattc_if 1
D (22130) BLE: Received GAP event 7 (ESP_GAP_BLE_SCAN_START_COMPLETE_EVT)
D (22250) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (22320) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (22320) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (22430) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (22540) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (22850) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (22960) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (23060) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
W (23110) BLE: Received GATTC event 18 (ESP_GATTC_CFG_MTU_EVT), gattc_if 1
I (23110) BLE2MQTT: Connected to device: 28:fd:80:07:b5:25, scanning
D (23120) MQTT: Subscribing to 28:fd:80:07:b5:25/Connected
D (23120) MQTT_CLIENT: mqtt_enqueue id: 33995, type=8 successful
D (23130) MQTT_CLIENT: Sent subscribe topic=28:fd:80:07:b5:25/Connected, id: 53441, type=8 successful
W (23140) BLE: Received GATTC event 7 (ESP_GATTC_SEARCH_RES_EVT), gattc_if 1
W (23140) BLE: GATTC event 7 wasn't handled
W (23150) BLE: Received GATTC event 7 (ESP_GATTC_SEARCH_RES_EVT), gattc_if 1
W (23160) BLE: GATTC event 7 wasn't handled
W (23160) BLE: Received GATTC event 7 (ESP_GATTC_SEARCH_RES_EVT), gattc_if 1
W (23170) BLE: GATTC event 7 wasn't handled
D (23170) MQTT_CLIENT: msg_type=9, msg_id=53441
W (23170) BLE: Received GATTC event 7 (ESP_GATTC_SEARCH_RES_EVT), gattc_if 1
D (23180) MQTT_CLIENT: msg_type=9, msg_id=53441
W (23180) BLE: GATTC event 7 wasn't handled
D (23190) MQTT_CLIENT: pending_id=53441, pending_msg_count = 1
W (23190) BLE: Received GATTC event 6 (ESP_GATTC_SEARCH_CMPL_EVT), gattc_if 1
D (23200) MQTT_CLIENT: Subscribe successful
D (23210) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (23210) BLE2MQTT: Services discovered on device: 28:fd:80:07:b5:25
D (23220) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (23230) BLE2MQTT: Found new characteristic!
D (23240) BLE2MQTT:   Service: 00001800-0000-1000-8000-00805f9b34fb
D (23240) BLE2MQTT:   Characteristic: 00002a00-0000-1000-8000-00805f9b34fb
D (23250) MQTT: Subscribing to 28:fd:80:07:b5:25/GenericAccess/DeviceName/Get
D (23260) MQTT_CLIENT: mqtt_enqueue id: 53441, type=8 successful
D (23260) MQTT_CLIENT: Sent subscribe topic=28:fd:80:07:b5:25/GenericAccess/DeviceName/Get, id: 19104, type=8 successful
D (23270) MQTT_CLIENT: msg_type=9, msg_id=19104
D (23280) MQTT_CLIENT: msg_type=9, msg_id=19104
W (23280) BLE: Enqueue: id: 1, type: 0, device: 28:fd:80:07:b5:25, char: 00002a00-0000-1000-8000-00805f9b34fb, len: 0, val: 0x0
D (23280) MQTT_CLIENT: pending_id=19104, pending_msg_count = 1
D (23300) BLE2MQTT: Found new characteristic!
D (23300) MQTT_CLIENT: Subscribe successful
D (23300) BLE2MQTT:   Service: 00001800-0000-1000-8000-00805f9b34fb
D (23310) BLE2MQTT:   Characteristic: 00002a01-0000-1000-8000-00805f9b34fb
D (23320) MQTT: Subscribing to 28:fd:80:07:b5:25/GenericAccess/Appearance/Get
D (23330) MQTT_CLIENT: mqtt_enqueue id: 19104, type=8 successful
D (23340) MQTT_CLIENT: Sent subscribe topic=28:fd:80:07:b5:25/GenericAccess/Appearance/Get, id: 4312, type=8 successful
W (23350) BLE: Enqueue: id: 2, type: 0, device: 28:fd:80:07:b5:25, char: 00002a01-0000-1000-8000-00805f9b34fb, len: 0, val: 0x0
D (23360) MQTT_CLIENT: msg_type=9, msg_id=4312
D (23360) BLE2MQTT: Found new characteristic!
D (23370) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (23360) MQTT_CLIENT: msg_type=9, msg_id=4312
D (23370) BLE2MQTT:   Service: 00001800-0000-1000-8000-00805f9b34fb
D (23380) MQTT_CLIENT: pending_id=4312, pending_msg_count = 1
D (23390) BLE2MQTT:   Characteristic: 00002a02-0000-1000-8000-00805f9b34fb
D (23390) MQTT_CLIENT: Subscribe successful
D (23400) MQTT: Subscribing to 28:fd:80:07:b5:25/GenericAccess/PeripheralPrivacyFlag/Get
D (23410) MQTT_CLIENT: mqtt_enqueue id: 4312, type=8 successful
D (23420) MQTT_CLIENT: Sent subscribe topic=28:fd:80:07:b5:25/GenericAccess/PeripheralPrivacyFlag/Get, id: 59304, type=8 successful
D (23420) MQTT_CLIENT: msg_type=9, msg_id=59304
W (23430) BLE: Enqueue: id: 3, type: 0, device: 28:fd:80:07:b5:25, char: 00002a02-0000-1000-8000-00805f9b34fb, len: 0, val: 0x0
D (23430) MQTT_CLIENT: msg_type=9, msg_id=59304
D (23450) MQTT_CLIENT: pending_id=59304, pending_msg_count = 1
D (23450) MQTT: Subscribing to 28:fd:80:07:b5:25/GenericAccess/PeripheralPrivacyFlag/Set
D (23450) MQTT_CLIENT: Subscribe successful
D (23470) MQTT_CLIENT: mqtt_enqueue id: 59304, type=8 successful
D (23470) MQTT_CLIENT: Sent subscribe topic=28:fd:80:07:b5:25/GenericAccess/PeripheralPrivacyFlag/Set, id: 19378, type=8 successful
D (23480) MQTT_CLIENT: msg_type=9, msg_id=19378
D (23490) BLE2MQTT: Found new characteristic!
D (23490) BLE2MQTT:   Service: 00001800-0000-1000-8000-00805f9b34fb
D (23490) MQTT_CLIENT: msg_type=9, msg_id=19378
D (23500) MQTT_CLIENT: pending_id=19378, pending_msg_count = 1
D (23510) BLE2MQTT:   Characteristic: 00002a04-0000-1000-8000-00805f9b34fb
D (23510) MQTT_CLIENT: Subscribe successful
D (23520) MQTT: Subscribing to 28:fd:80:07:b5:25/GenericAccess/PeripheralPreferredConnectionParameters/Get
D (23530) MQTT_CLIENT: mqtt_enqueue id: 19378, type=8 successful
D (23540) MQTT_CLIENT: Sent subscribe topic=28:fd:80:07:b5:25/GenericAccess/PeripheralPreferredConnectionParameters/Get, id: 3525, type=8 successful
D (23540) MQTT_CLIENT: msg_type=9, msg_id=3525
D (23560) MQTT_CLIENT: msg_type=9, msg_id=3525
W (23560) BLE: Enqueue: id: 4, type: 0, device: 28:fd:80:07:b5:25, char: 00002a04-0000-1000-8000-00805f9b34fb, len: 0, val: 0x0
D (23560) MQTT_CLIENT: pending_id=3525, pending_msg_count = 1
D (23580) MQTT_CLIENT: Subscribe successful
D (23580) BLE2MQTT: Found new characteristic!
D (23590) BLE2MQTT:   Service: 00001801-0000-1000-8000-00805f9b34fb
D (23590) BLE2MQTT:   Characteristic: 00002a05-0000-1000-8000-00805f9b34fb
D (23600) BLE2MQTT: Found new characteristic!
D (23600) BLE2MQTT:   Service: 0000180a-0000-1000-8000-00805f9b34fb
D (23610) BLE2MQTT:   Characteristic: 00002a29-0000-1000-8000-00805f9b34fb
D (23620) MQTT: Subscribing to 28:fd:80:07:b5:25/DeviceInformation/ManufacturerNameString/Get
D (23630) MQTT_CLIENT: mqtt_enqueue id: 3525, type=8 successful
D (23630) MQTT_CLIENT: Sent subscribe topic=28:fd:80:07:b5:25/DeviceInformation/ManufacturerNameString/Get, id: 56390, type=8 successful
D (23640) MQTT_CLIENT: msg_type=9, msg_id=56390
D (23650) MQTT_CLIENT: msg_type=9, msg_id=56390
W (23650) BLE: Enqueue: id: 5, type: 0, device: 28:fd:80:07:b5:25, char: 00002a29-0000-1000-8000-00805f9b34fb, len: 0, val: 0x0
D (23650) MQTT_CLIENT: pending_id=56390, pending_msg_count = 1
D (23670) BLE2MQTT: Found new characteristic!
D (23670) MQTT_CLIENT: Subscribe successful
D (23680) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (23680) BLE2MQTT:   Service: 0000180a-0000-1000-8000-00805f9b34fb
D (23690) BLE2MQTT:   Characteristic: 00002a24-0000-1000-8000-00805f9b34fb
D (23700) MQTT: Subscribing to 28:fd:80:07:b5:25/DeviceInformation/ModelNumberString/Get
D (23710) MQTT_CLIENT: mqtt_enqueue id: 56390, type=8 successful
D (23720) MQTT_CLIENT: Sent subscribe topic=28:fd:80:07:b5:25/DeviceInformation/ModelNumberString/Get, id: 16472, type=8 successful
D (23720) MQTT_CLIENT: msg_type=9, msg_id=16472
W (23730) BLE: Enqueue: id: 6, type: 0, device: 28:fd:80:07:b5:25, char: 00002a24-0000-1000-8000-00805f9b34fb, len: 0, val: 0x0
D (23730) MQTT_CLIENT: msg_type=9, msg_id=16472
D (23750) MQTT_CLIENT: pending_id=16472, pending_msg_count = 1
D (23750) BLE2MQTT: Found new characteristic!
D (23750) MQTT_CLIENT: Subscribe successful
D (23760) BLE2MQTT:   Service: 0000180a-0000-1000-8000-00805f9b34fb
D (23770) BLE2MQTT:   Characteristic: 00002a26-0000-1000-8000-00805f9b34fb
D (23780) MQTT: Subscribing to 28:fd:80:07:b5:25/DeviceInformation/FirmwareRevisionString/Get
D (23780) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (23780) MQTT_CLIENT: mqtt_enqueue id: 16472, type=8 successful
D (23800) MQTT_CLIENT: Sent subscribe topic=28:fd:80:07:b5:25/DeviceInformation/FirmwareRevisionString/Get, id: 28639, type=8 successful
D (23800) MQTT_CLIENT: msg_type=9, msg_id=28639
W (23810) BLE: Enqueue: id: 7, type: 0, device: 28:fd:80:07:b5:25, char: 00002a26-0000-1000-8000-00805f9b34fb, len: 0, val: 0x0
D (23810) MQTT_CLIENT: msg_type=9, msg_id=28639
D (23830) BLE2MQTT: Found new characteristic!
D (23830) MQTT_CLIENT: pending_id=28639, pending_msg_count = 1
D (23840) BLE2MQTT:   Service: 0000180a-0000-1000-8000-00805f9b34fb
D (23840) MQTT_CLIENT: Subscribe successful
D (23850) BLE2MQTT:   Characteristic: 00002a28-0000-1000-8000-00805f9b34fb
D (23860) MQTT: Subscribing to 28:fd:80:07:b5:25/DeviceInformation/SoftwareRevisionString/Get
D (23870) MQTT_CLIENT: mqtt_enqueue id: 28639, type=8 successful
D (23870) MQTT_CLIENT: Sent subscribe topic=28:fd:80:07:b5:25/DeviceInformation/SoftwareRevisionString/Get, id: 23875, type=8 successful
D (23880) MQTT_CLIENT: msg_type=9, msg_id=23875
D (23890) MQTT_CLIENT: msg_type=9, msg_id=23875
W (23890) BLE: Enqueue: id: 8, type: 0, device: 28:fd:80:07:b5:25, char: 00002a28-0000-1000-8000-00805f9b34fb, len: 0, val: 0x0
D (23890) MQTT_CLIENT: pending_id=23875, pending_msg_count = 1
D (23910) BLE2MQTT: Found new characteristic!
D (23910) MQTT_CLIENT: Subscribe successful
D (23920) BLE2MQTT:   Service: 0000180a-0000-1000-8000-00805f9b34fb
D (23930) BLE2MQTT:   Characteristic: 00002a23-0000-1000-8000-00805f9b34fb
D (23930) MQTT: Subscribing to 28:fd:80:07:b5:25/DeviceInformation/SystemID/Get
D (23940) MQTT_CLIENT: mqtt_enqueue id: 23875, type=8 successful
D (23950) MQTT_CLIENT: Sent subscribe topic=28:fd:80:07:b5:25/DeviceInformation/SystemID/Get, id: 20371, type=8 successful
W (23960) BLE: Enqueue: id: 9, type: 0, device: 28:fd:80:07:b5:25, char: 00002a23-0000-1000-8000-00805f9b34fb, len: 0, val: 0x0
D (23960) MQTT_CLIENT: msg_type=9, msg_id=20371
D (23980) MQTT_CLIENT: msg_type=9, msg_id=20371
D (23980) BLE2MQTT: Found new characteristic!
D (23980) MQTT_CLIENT: pending_id=20371, pending_msg_count = 1
D (23990) BLE2MQTT:   Service: 0000180a-0000-1000-8000-00805f9b34fb
D (23990) MQTT_CLIENT: Subscribe successful
D (24000) BLE2MQTT:   Characteristic: 00002a50-0000-1000-8000-00805f9b34fb
D (24010) MQTT: Subscribing to 28:fd:80:07:b5:25/DeviceInformation/PnPID/Get
D (24010) MQTT_CLIENT: mqtt_enqueue id: 20371, type=8 successful
D (24020) MQTT_CLIENT: Sent subscribe topic=28:fd:80:07:b5:25/DeviceInformation/PnPID/Get, id: 18699, type=8 successful
D (24030) MQTT_CLIENT: msg_type=9, msg_id=18699
D (24040) MQTT_CLIENT: msg_type=9, msg_id=18699
W (24040) BLE: Enqueue: id: 10, type: 0, device: 28:fd:80:07:b5:25, char: 00002a50-0000-1000-8000-00805f9b34fb, len: 0, val: 0x0
D (24040) MQTT_CLIENT: pending_id=18699, pending_msg_count = 1
D (24060) MQTT_CLIENT: Subscribe successful
D (24060) BLE2MQTT: Found new characteristic!
D (24070) BLE2MQTT:   Service: 00001810-0000-1000-8000-00805f9b34fb
D (24070) BLE2MQTT:   Characteristic: 00002a35-0000-1000-8000-00805f9b34fb
I (24080) BLE: Indication registered: 00002a35-0000-1000-8000-00805f9b34fb
W (24080) BLE: Received GATTC event 38 (ESP_GATTC_REG_FOR_NOTIFY_EVT), gattc_if 1
W (24090) BLE: Enqueue: id: 11, type: 2, device: 28:fd:80:07:b5:25, char: 00002a35-0000-1000-8000-00805f9b34fb, len: 2, val: 0x3ffd37d4
D (24110) BLE2MQTT: Found new characteristic!
D (24110) BLE2MQTT:   Service: 00001810-0000-1000-8000-00805f9b34fb
D (24120) BLE2MQTT:   Characteristic: 00002a49-0000-1000-8000-00805f9b34fb
D (24380) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
W (24610) BLE: Queue timer expired
W (24610) BLE: Dequeue: id: 1, type: 0, device: 28:fd:80:07:b5:25, char: 00002a00-0000-1000-8000-00805f9b34fb, len: 0, val: 0x0
W (24700) BLE: Received GATTC event 3 (ESP_GATTC_READ_CHAR_EVT), gattc_if 1
W (24700) BLE: Dequeue: id: 2, type: 0, device: 28:fd:80:07:b5:25, char: 00002a00-0000-1000-8000-00805f9b34fb, len: 0, val: 0x0
I (24700) BLE2MQTT: Publishing: 28:fd:80:07:b5:25/GenericAccess/DeviceName = BC85
W (24760) BLE: Received GATTC event 3 (ESP_GATTC_READ_CHAR_EVT), gattc_if 1
W (24760) BLE: Dequeue: id: 3, type: 0, device: 28:fd:80:07:b5:25, char: 00002a01-0000-1000-8000-00805f9b34fb, len: 0, val: 0x0
I (24760) BLE2MQTT: Publishing: 28:fd:80:07:b5:25/GenericAccess/Appearance = 0
W (24790) BLE: Received GATTC event 3 (ESP_GATTC_READ_CHAR_EVT), gattc_if 1
W (24790) BLE: Dequeue: id: 4, type: 0, device: 28:fd:80:07:b5:25, char: 00002a02-0000-1000-8000-00805f9b34fb, len: 0, val: 0x0
I (24790) BLE2MQTT: Publishing: 28:fd:80:07:b5:25/GenericAccess/PeripheralPrivacyFlag = false
W (24880) BLE: Received GATTC event 3 (ESP_GATTC_READ_CHAR_EVT), gattc_if 1
W (24880) BLE: Dequeue: id: 5, type: 0, device: 28:fd:80:07:b5:25, char: 00002a04-0000-1000-8000-00805f9b34fb, len: 0, val: 0x0
I (24880) BLE2MQTT: Publishing: 28:fd:80:07:b5:25/GenericAccess/PeripheralPreferredConnectionParameters = 8,16,0,100
W (24980) BLE: Received GATTC event 3 (ESP_GATTC_READ_CHAR_EVT), gattc_if 1
W (24980) BLE: Dequeue: id: 6, type: 0, device: 28:fd:80:07:b5:25, char: 00002a24-0000-1000-8000-00805f9b34fb, len: 0, val: 0x0
I (24980) BLE2MQTT: Publishing: 28:fd:80:07:b5:25/DeviceInformation/ManufacturerNameString = Dialog Semi
W (25030) BLE: Received GATTC event 3 (ESP_GATTC_READ_CHAR_EVT), gattc_if 1
W (25030) BLE: Dequeue: id: 7, type: 0, device: 28:fd:80:07:b5:25, char: 00002a24-0000-1000-8000-00805f9b34fb, len: 0, val: 0x0
I (25030) BLE2MQTT: Publishing: 28:fd:80:07:b5:25/DeviceInformation/ModelNumberString = DA14580
W (25070) BLE: Received GATTC event 3 (ESP_GATTC_READ_CHAR_EVT), gattc_if 1
W (25080) BLE: Dequeue: id: 8, type: 0, device: 28:fd:80:07:b5:25, char: 00002a26-0000-1000-8000-00805f9b34fb, len: 0, val: 0x0
I (25080) BLE2MQTT: Publishing: 28:fd:80:07:b5:25/DeviceInformation/FirmwareRevisionString = v8.1
W (25150) BLE: Received GATTC event 3 (ESP_GATTC_READ_CHAR_EVT), gattc_if 1
W (25150) BLE: Dequeue: id: 9, type: 0, device: 28:fd:80:07:b5:25, char: 00002a28-0000-1000-8000-00805f9b34fb, len: 0, val: 0x0
I (25150) BLE2MQTT: Publishing: 28:fd:80:07:b5:25/DeviceInformation/SoftwareRevisionString = v_3.150.1.5
W (25190) BLE: Received GATTC event 3 (ESP_GATTC_READ_CHAR_EVT), gattc_if 1
W (25190) BLE: Dequeue: id: 10, type: 0, device: 28:fd:80:07:b5:25, char: 00002a23-0000-1000-8000-00805f9b34fb, len: 0, val: 0x0
I (25190) BLE2MQTT: Publishing: 28:fd:80:07:b5:25/DeviceInformation/SystemID = 18446744073698423826,14597274
W (25240) BLE: Received GATTC event 3 (ESP_GATTC_READ_CHAR_EVT), gattc_if 1
W (25240) BLE: Dequeue: id: 11, type: 2, device: 28:fd:80:07:b5:25, char: 00002a50-0000-1000-8000-00805f9b34fb, len: 2, val: 0x3ffd37d4
I (25240) BLE2MQTT: Publishing: 28:fd:80:07:b5:25/DeviceInformation/PnPID = 1,210,1408,256
W (25390) BLE: Received GATTC event 9 (ESP_GATTC_WRITE_DESCR_EVT), gattc_if 1
D (25700) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (26630) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (26950) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (27230) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (27330) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (27370) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (27530) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (27640) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (27740) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (27850) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (27950) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
W (28070) BT_APPL: bta_gattc_conn_cback() - cif=1 connected=0 conn_id=1 reason=0x0013
W (28070) BLE: Received GATTC event 41 (ESP_GATTC_DISCONNECT_EVT), gattc_if 1
W (28080) BLE: GATTC event 41 wasn't handled
W (28080) BLE: Received GATTC event 5 (ESP_GATTC_CLOSE_EVT), gattc_if 1
I (28090) BLE: Connection closed, reason = 0x13
I (28100) BLE2MQTT: Disconnected from device: 28:fd:80:07:b5:25
D (28100) MQTT: Unsubscribing from 28:fd:80:07:b5:25/Connected
D (28110) MQTT_CLIENT: mqtt_enqueue id: 18699, type=8 successful
D (28110) MQTT_CLIENT: unsubscribe, topic"28:fd:80:07:b5:25/Connected", id: 58361
D (28120) MQTT_CLIENT: Sent Unsubscribe topic=28:fd:80:07:b5:25/Connected, id: 58361, successful
D (28130) MQTT_CLIENT: msg_type=11, msg_id=58361
D (28140) MQTT_CLIENT: msg_type=11, msg_id=58361
D (28140) MQTT_CLIENT: pending_id=58361, pending_msg_count = 1
D (28150) MQTT_CLIENT: UnSubscribe successful
D (28160) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (28370) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (28480) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (28580) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (28670) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (28690) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (28780) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (28790) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (28900) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (29000) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (29110) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (29220) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (29320) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (29420) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (29520) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (29620) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (29720) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (29800) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (29930) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (30030) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (30130) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
bilogic commented 5 years ago

I added another ESP_LOGW inside ble_operation_perform(), to my surprise, it matches Enqueue. And somehow, it is only the characteristics that is wrong, the other values, e.g. type, is correct. Basically,

Enquene11: 0x2935 Dequeue11: 0x2950 Perform11: 0x2935

This makes debugging (this and other issues) very challenging as I don't know when the logs can be trusted.

W (39550) BLE: Enqueue: id: 1, type: 0, device: 28:fd:80:07:b5:25, char: 00002a00-0000-1000-8000-00805f9b34fb, len: 0, val: 0x0
D (39550) MQTT_CLIENT: msg_type=9, msg_id=52032
D (39570) MQTT_CLIENT: pending_id=52032, pending_msg_count = 1
D (39570) BLE2MQTT: Found new characteristic!
D (39570) MQTT_CLIENT: Subscribe successful
D (39580) BLE2MQTT:   Service: 00001800-0000-1000-8000-00805f9b34fb
D (39590) BLE2MQTT:   Characteristic: 00002a01-0000-1000-8000-00805f9b34fb
D (39600) MQTT: Subscribing to 28:fd:80:07:b5:25/GenericAccess/Appearance/Get
D (39600) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (39600) MQTT_CLIENT: mqtt_enqueue id: 52032, type=8 successful
D (39620) MQTT_CLIENT: Sent subscribe topic=28:fd:80:07:b5:25/GenericAccess/Appearance/Get, id: 40884, type=8 successful
W (39630) BLE: Enqueue: id: 2, type: 0, device: 28:fd:80:07:b5:25, char: 00002a01-0000-1000-8000-00805f9b34fb, len: 0, val: 0x0
D (39630) MQTT_CLIENT: msg_type=9, msg_id=40884
D (39640) BLE2MQTT: Found new characteristic!
D (39640) MQTT_CLIENT: msg_type=9, msg_id=40884
D (39650) BLE2MQTT:   Service: 00001800-0000-1000-8000-00805f9b34fb
D (39660) MQTT_CLIENT: pending_id=40884, pending_msg_count = 1
D (39660) BLE2MQTT:   Characteristic: 00002a02-0000-1000-8000-00805f9b34fb
D (39670) MQTT_CLIENT: Subscribe successful
D (39680) MQTT: Subscribing to 28:fd:80:07:b5:25/GenericAccess/PeripheralPrivacyFlag/Get
D (39680) MQTT_CLIENT: mqtt_enqueue id: 40884, type=8 successful
D (39690) MQTT_CLIENT: Sent subscribe topic=28:fd:80:07:b5:25/GenericAccess/PeripheralPrivacyFlag/Get, id: 23624, type=8 successful
D (39700) MQTT_CLIENT: msg_type=9, msg_id=23624
D (39710) MQTT_CLIENT: msg_type=9, msg_id=23624
W (39710) BLE: Enqueue: id: 3, type: 0, device: 28:fd:80:07:b5:25, char: 00002a02-0000-1000-8000-00805f9b34fb, len: 0, val: 0x0
D (39720) MQTT_CLIENT: pending_id=23624, pending_msg_count = 1
D (39730) MQTT_CLIENT: Subscribe successful
D (39730) MQTT: Subscribing to 28:fd:80:07:b5:25/GenericAccess/PeripheralPrivacyFlag/Set
D (39740) MQTT_CLIENT: mqtt_enqueue id: 23624, type=8 successful
D (39750) MQTT_CLIENT: Sent subscribe topic=28:fd:80:07:b5:25/GenericAccess/PeripheralPrivacyFlag/Set, id: 61514, type=8 successful
D (39750) MQTT_CLIENT: msg_type=9, msg_id=61514
D (39760) BLE2MQTT: Found new characteristic!
D (39760) MQTT_CLIENT: msg_type=9, msg_id=61514
D (39770) BLE2MQTT:   Service: 00001800-0000-1000-8000-00805f9b34fb
D (39780) MQTT_CLIENT: pending_id=61514, pending_msg_count = 1
D (39780) BLE2MQTT:   Characteristic: 00002a04-0000-1000-8000-00805f9b34fb
D (39780) MQTT_CLIENT: Subscribe successful
D (39800) MQTT: Subscribing to 28:fd:80:07:b5:25/GenericAccess/PeripheralPreferredConnectionParameters/Get
D (39810) MQTT_CLIENT: mqtt_enqueue id: 61514, type=8 successful
D (39810) MQTT_CLIENT: Sent subscribe topic=28:fd:80:07:b5:25/GenericAccess/PeripheralPreferredConnectionParameters/Get, id: 24847, type=8 successful
D (39820) MQTT_CLIENT: msg_type=9, msg_id=24847
W (39830) BLE: Enqueue: id: 4, type: 0, device: 28:fd:80:07:b5:25, char: 00002a04-0000-1000-8000-00805f9b34fb, len: 0, val: 0x0
D (39830) MQTT_CLIENT: msg_type=9, msg_id=24847
D (39850) MQTT_CLIENT: pending_id=24847, pending_msg_count = 1
D (39850) BLE2MQTT: Found new characteristic!
D (39850) MQTT_CLIENT: Subscribe successful
D (39860) BLE2MQTT:   Service: 00001801-0000-1000-8000-00805f9b34fb
D (39870) BLE2MQTT:   Characteristic: 00002a05-0000-1000-8000-00805f9b34fb
D (39870) BLE2MQTT: Found new characteristic!
D (39880) BLE2MQTT:   Service: 0000180a-0000-1000-8000-00805f9b34fb
D (39890) BLE2MQTT:   Characteristic: 00002a29-0000-1000-8000-00805f9b34fb
D (39890) MQTT: Subscribing to 28:fd:80:07:b5:25/DeviceInformation/ManufacturerNameString/Get
D (39900) MQTT_CLIENT: mqtt_enqueue id: 24847, type=8 successful
D (39910) MQTT_CLIENT: Sent subscribe topic=28:fd:80:07:b5:25/DeviceInformation/ManufacturerNameString/Get, id: 64509, type=8 successful
D (39920) MQTT_CLIENT: msg_type=9, msg_id=64509
W (39920) BLE: Enqueue: id: 5, type: 0, device: 28:fd:80:07:b5:25, char: 00002a29-0000-1000-8000-00805f9b34fb, len: 0, val: 0x0
D (39930) MQTT_CLIENT: msg_type=9, msg_id=64509
D (39940) BLE2MQTT: Found new characteristic!
D (39940) MQTT_CLIENT: pending_id=64509, pending_msg_count = 1
D (39950) BLE2MQTT:   Service: 0000180a-0000-1000-8000-00805f9b34fb
D (39960) MQTT_CLIENT: Subscribe successful
D (39960) BLE2MQTT:   Characteristic: 00002a24-0000-1000-8000-00805f9b34fb
D (39970) MQTT: Subscribing to 28:fd:80:07:b5:25/DeviceInformation/ModelNumberString/Get
D (39980) MQTT_CLIENT: mqtt_enqueue id: 64509, type=8 successful
D (39980) MQTT_CLIENT: Sent subscribe topic=28:fd:80:07:b5:25/DeviceInformation/ModelNumberString/Get, id: 33729, type=8 successful
D (39990) MQTT_CLIENT: msg_type=9, msg_id=33729
D (40000) MQTT_CLIENT: msg_type=9, msg_id=33729
W (40000) BLE: Enqueue: id: 6, type: 0, device: 28:fd:80:07:b5:25, char: 00002a24-0000-1000-8000-00805f9b34fb, len: 0, val: 0x0
D (40020) BLE2MQTT: Found new characteristic!
D (40010) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (40000) MQTT_CLIENT: pending_id=33729, pending_msg_count = 1
D (40020) BLE2MQTT:   Service: 0000180a-0000-1000-8000-00805f9b34fb
D (40030) MQTT_CLIENT: Subscribe successful
D (40040) BLE2MQTT:   Characteristic: 00002a26-0000-1000-8000-00805f9b34fb
D (40050) MQTT: Subscribing to 28:fd:80:07:b5:25/DeviceInformation/FirmwareRevisionString/Get
D (40060) MQTT_CLIENT: mqtt_enqueue id: 33729, type=8 successful
D (40070) MQTT_CLIENT: Sent subscribe topic=28:fd:80:07:b5:25/DeviceInformation/FirmwareRevisionString/Get, id: 1848, type=8 successful
D (40070) MQTT_CLIENT: msg_type=9, msg_id=1848
W (40080) BLE: Enqueue: id: 7, type: 0, device: 28:fd:80:07:b5:25, char: 00002a26-0000-1000-8000-00805f9b34fb, len: 0, val: 0x0
D (40080) MQTT_CLIENT: msg_type=9, msg_id=1848
D (40100) MQTT_CLIENT: pending_id=1848, pending_msg_count = 1
D (40100) BLE2MQTT: Found new characteristic!
D (40100) MQTT_CLIENT: Subscribe successful
D (40110) BLE2MQTT:   Service: 0000180a-0000-1000-8000-00805f9b34fb
D (40120) BLE2MQTT:   Characteristic: 00002a28-0000-1000-8000-00805f9b34fb
D (40130) MQTT: Subscribing to 28:fd:80:07:b5:25/DeviceInformation/SoftwareRevisionString/Get
D (40130) MQTT_CLIENT: mqtt_enqueue id: 1848, type=8 successful
D (40140) MQTT_CLIENT: Sent subscribe topic=28:fd:80:07:b5:25/DeviceInformation/SoftwareRevisionString/Get, id: 6144, type=8 successful
D (40150) MQTT_CLIENT: msg_type=9, msg_id=6144
D (40160) MQTT_CLIENT: msg_type=9, msg_id=6144
W (40160) BLE: Enqueue: id: 8, type: 0, device: 28:fd:80:07:b5:25, char: 00002a28-0000-1000-8000-00805f9b34fb, len: 0, val: 0x0
D (40170) MQTT_CLIENT: pending_id=6144, pending_msg_count = 1
D (40180) BLE2MQTT: Found new characteristic!
D (40180) MQTT_CLIENT: Subscribe successful
D (40190) BLE2MQTT:   Service: 0000180a-0000-1000-8000-00805f9b34fb
D (40190) BLE2MQTT:   Characteristic: 00002a23-0000-1000-8000-00805f9b34fb
D (40200) MQTT: Subscribing to 28:fd:80:07:b5:25/DeviceInformation/SystemID/Get
D (40210) MQTT_CLIENT: mqtt_enqueue id: 6144, type=8 successful
D (40220) MQTT_CLIENT: Sent subscribe topic=28:fd:80:07:b5:25/DeviceInformation/SystemID/Get, id: 35781, type=8 successful
W (40230) BLE: Enqueue: id: 9, type: 0, device: 28:fd:80:07:b5:25, char: 00002a23-0000-1000-8000-00805f9b34fb, len: 0, val: 0x0
D (40230) MQTT_CLIENT: msg_type=9, msg_id=35781
D (40240) BLE2MQTT: Found new characteristic!
D (40240) MQTT_CLIENT: msg_type=9, msg_id=35781
D (40250) BLE2MQTT:   Service: 0000180a-0000-1000-8000-00805f9b34fb
D (40250) MQTT_CLIENT: pending_id=35781, pending_msg_count = 1
D (40260) BLE2MQTT:   Characteristic: 00002a50-0000-1000-8000-00805f9b34fb
D (40270) MQTT_CLIENT: Subscribe successful
D (40280) MQTT: Subscribing to 28:fd:80:07:b5:25/DeviceInformation/PnPID/Get
D (40280) MQTT_CLIENT: mqtt_enqueue id: 35781, type=8 successful
D (40290) MQTT_CLIENT: Sent subscribe topic=28:fd:80:07:b5:25/DeviceInformation/PnPID/Get, id: 47957, type=8 successful
D (40300) MQTT_CLIENT: msg_type=9, msg_id=47957
W (40300) BLE: Enqueue: id: 10, type: 0, device: 28:fd:80:07:b5:25, char: 00002a50-0000-1000-8000-00805f9b34fb, len: 0, val: 0x0
D (40320) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (40300) MQTT_CLIENT: msg_type=9, msg_id=47957
D (40320) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (40320) BLE2MQTT: Found new characteristic!
D (40330) MQTT_CLIENT: pending_id=47957, pending_msg_count = 1
D (40340) BLE2MQTT:   Service: 00001810-0000-1000-8000-00805f9b34fb
D (40350) MQTT_CLIENT: Subscribe successful
D (40350) BLE2MQTT:   Characteristic: 00002a35-0000-1000-8000-00805f9b34fb
W (40360) BLE: Received GATTC event 38 (ESP_GATTC_REG_FOR_NOTIFY_EVT), gattc_if 1
I (40360) BLE: Indication registered: 00002a35-0000-1000-8000-00805f9b34fb
W (40380) BLE: Enqueue: id: 11, type: 2, device: 28:fd:80:07:b5:25, char: 00002a35-0000-1000-8000-00805f9b34fb, len: 2, val: 0x3ffbab28
D (40390) BLE2MQTT: Found new characteristic!
D (40390) BLE2MQTT:   Service: 00001810-0000-1000-8000-00805f9b34fb
D (40400) BLE2MQTT:   Characteristic: 00002a49-0000-1000-8000-00805f9b34fb
D (40840) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
W (40890) BLE: Queue timer expired
W (40890) BLE: Dequeue: id: 1, type: 0, device: 28:fd:80:07:b5:25, char: 00002a00-0000-1000-8000-00805f9b34fb, len: 0, val: 0x0
W (40890) BLE: Perform: id: 1, type: 0, device: 28:fd:80:07:b5:25, char: 00002a00-0000-1000-8000-00805f9b34fb, len: 0, val: 0x0
D (40950) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
W (40950) BLE: Received GATTC event 3 (ESP_GATTC_READ_CHAR_EVT), gattc_if 1
W (40950) BLE: Dequeue: id: 2, type: 0, device: 28:fd:80:07:b5:25, char: 00002a00-0000-1000-8000-00805f9b34fb, len: 0, val: 0x0
I (40950) BLE2MQTT: Publishing: 28:fd:80:07:b5:25/GenericAccess/DeviceName = BC85
W (40960) BLE: Perform: id: 2, type: 0, device: 28:fd:80:07:b5:25, char: 00002a01-0000-1000-8000-00805f9b34fb, len: 0, val: 0x0
W (41130) BLE: Received GATTC event 3 (ESP_GATTC_READ_CHAR_EVT), gattc_if 1
W (41130) BLE: Dequeue: id: 3, type: 0, device: 28:fd:80:07:b5:25, char: 00002a01-0000-1000-8000-00805f9b34fb, len: 0, val: 0x0
I (41130) BLE2MQTT: Publishing: 28:fd:80:07:b5:25/GenericAccess/Appearance = 0
W (41140) BLE: Perform: id: 3, type: 0, device: 28:fd:80:07:b5:25, char: 00002a02-0000-1000-8000-00805f9b34fb, len: 0, val: 0x0
W (41250) BLE: Received GATTC event 3 (ESP_GATTC_READ_CHAR_EVT), gattc_if 1
W (41250) BLE: Dequeue: id: 4, type: 0, device: 28:fd:80:07:b5:25, char: 00002a02-0000-1000-8000-00805f9b34fb, len: 0, val: 0x0
I (41250) BLE2MQTT: Publishing: 28:fd:80:07:b5:25/GenericAccess/PeripheralPrivacyFlag = false
W (41260) BLE: Perform: id: 4, type: 0, device: 28:fd:80:07:b5:25, char: 00002a04-0000-1000-8000-00805f9b34fb, len: 0, val: 0x0
D (41280) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (41350) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
W (41360) BLE: Received GATTC event 3 (ESP_GATTC_READ_CHAR_EVT), gattc_if 1
W (41360) BLE: Dequeue: id: 5, type: 0, device: 28:fd:80:07:b5:25, char: 00002a04-0000-1000-8000-00805f9b34fb, len: 0, val: 0x0
I (41360) BLE2MQTT: Publishing: 28:fd:80:07:b5:25/GenericAccess/PeripheralPreferredConnectionParameters = 8,16,0,100
W (41370) BLE: Perform: id: 5, type: 0, device: 28:fd:80:07:b5:25, char: 00002a29-0000-1000-8000-00805f9b34fb, len: 0, val: 0x0
D (41390) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
W (41460) BLE: Received GATTC event 3 (ESP_GATTC_READ_CHAR_EVT), gattc_if 1
W (41460) BLE: Dequeue: id: 6, type: 0, device: 28:fd:80:07:b5:25, char: 00002a29-0000-1000-8000-00805f9b34fb, len: 0, val: 0x0
I (41460) BLE2MQTT: Publishing: 28:fd:80:07:b5:25/DeviceInformation/ManufacturerNameString = Dialog Semi
W (41470) BLE: Perform: id: 6, type: 0, device: 28:fd:80:07:b5:25, char: 00002a24-0000-1000-8000-00805f9b34fb, len: 0, val: 0x0
W (41570) BLE: Received GATTC event 3 (ESP_GATTC_READ_CHAR_EVT), gattc_if 1
W (41570) BLE: Dequeue: id: 7, type: 0, device: 28:fd:80:07:b5:25, char: 00002a24-0000-1000-8000-00805f9b34fb, len: 0, val: 0x0
I (41570) BLE2MQTT: Publishing: 28:fd:80:07:b5:25/DeviceInformation/ModelNumberString = DA14580
W (41580) BLE: Perform: id: 7, type: 0, device: 28:fd:80:07:b5:25, char: 00002a26-0000-1000-8000-00805f9b34fb, len: 0, val: 0x0
W (41750) BLE: Received GATTC event 3 (ESP_GATTC_READ_CHAR_EVT), gattc_if 1
W (41750) BLE: Dequeue: id: 8, type: 0, device: 28:fd:80:07:b5:25, char: 00002a26-0000-1000-8000-00805f9b34fb, len: 0, val: 0x0
I (41750) BLE2MQTT: Publishing: 28:fd:80:07:b5:25/DeviceInformation/FirmwareRevisionString = v8.1
W (41760) BLE: Perform: id: 8, type: 0, device: 28:fd:80:07:b5:25, char: 00002a28-0000-1000-8000-00805f9b34fb, len: 0, val: 0x0
W (41850) BLE: Received GATTC event 3 (ESP_GATTC_READ_CHAR_EVT), gattc_if 1
W (41850) BLE: Dequeue: id: 9, type: 0, device: 28:fd:80:07:b5:25, char: 00002a28-0000-1000-8000-00805f9b34fb, len: 0, val: 0x0
I (41850) BLE2MQTT: Publishing: 28:fd:80:07:b5:25/DeviceInformation/SoftwareRevisionString = v_3.150.1.5
W (41860) BLE: Perform: id: 9, type: 0, device: 28:fd:80:07:b5:25, char: 00002a23-0000-1000-8000-00805f9b34fb, len: 0, val: 0x0
W (41970) BLE: Received GATTC event 3 (ESP_GATTC_READ_CHAR_EVT), gattc_if 1
W (41970) BLE: Dequeue: id: 10, type: 0, device: 28:fd:80:07:b5:25, char: 00002a23-0000-1000-8000-00805f9b34fb, len: 0, val: 0x0
I (41980) BLE2MQTT: Publishing: 28:fd:80:07:b5:25/DeviceInformation/SystemID = 18446744073698423826,14597274
W (41980) BLE: Perform: id: 10, type: 0, device: 28:fd:80:07:b5:25, char: 00002a50-0000-1000-8000-00805f9b34fb, len: 0, val: 0x0
W (42150) BLE: Received GATTC event 3 (ESP_GATTC_READ_CHAR_EVT), gattc_if 1
W (42150) BLE: Dequeue: id: 11, type: 2, device: 28:fd:80:07:b5:25, char: 00002a50-0000-1000-8000-00805f9b34fb, len: 2, val: 0x3ffbab28
I (42160) BLE2MQTT: Publishing: 28:fd:80:07:b5:25/DeviceInformation/PnPID = 1,210,1408,256
W (42160) BLE: Perform: id: 11, type: 2, device: 28:fd:80:07:b5:25, char: 00002a35-0000-1000-8000-00805f9b34fb, len: 2, val: 0x3ffbab28
W (42290) BLE: Received GATTC event 9 (ESP_GATTC_WRITE_DESCR_EVT), gattc_if 1
D (42500) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (43930) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (44000) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (44100) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (44210) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (44310) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (44410) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (44520) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (44620) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (44830) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (44940) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
D (44940) BLE: Received GAP event 3 (ESP_GAP_BLE_SCAN_RESULT_EVT)
W (45050) BT_APPL: bta_gattc_conn_cback() - cif=1 connected=0 conn_id=1 reason=0x0013
W (45050) BLE: Received GATTC event 41 (ESP_GATTC_DISCONNECT_EVT), gattc_if 1
W (45050) BLE: GATTC event 41 wasn't handled
W (45060) BLE: Received GATTC event 5 (ESP_GATTC_CLOSE_EVT), gattc_if 1
I (45070) BLE: Connection closed, reason = 0x13
I (45070) BLE2MQTT: Disconnected from device: 28:fd:80:07:b5:25
D (45080) MQTT: Unsubscribing from 28:fd:80:07:b5:25/Connected
D (45080) MQTT_CLIENT: mqtt_enqueue id: 47957, type=8 successful
bilogic commented 5 years ago

This is very troubling, I commented out Dequeue, now Perform is wrong.

Earlier Enqueue: 0x2935 Dequeue: 0x2950 Perform: 0x2935

Now Enqueue: 0x2935 // Dequeue: N/A Perform: 0x2950

I have no idea what is being actually sent.

My real issue with a blood pressure device is:

  1. The device stores values in its memory and can be retrieved by registering for indications from characteristics 0x2A35 and sending 0x2902
  2. On another piece of BLE ESP32 code, after doing .1, I get a series of callback via ESP_GATTC_NOTIFY_EVT
  3. However, in esp32-ble2mqtt, after doing .1, there are no ESP_GATTC_NOTIFY_EVT events received
shmuelzon commented 5 years ago

Hey,

So, first off, the thing to note about the uuidtoa() function is that it's not really thread-safe. It returns a pointer to a static buffer so each call won't allocate and the caller won't need to free anything. This is usually not a problem since it's mainly used for logging and usually most logs are disabled. If you want to make sure you print what you expect then you'll need the following replacement:

    ESP_LOGD(TAG, "  Service: %s", uuidtoa(service_uuid));

With:

    ESP_LOGD(TAG, "  Service: %02x%02x%02x%02x-%02x%02x-%02x%02x-%02x%02x-%02x%02x%02x%02x%02x%02x", uuid[15], uuid[14], uuid[13], uuid[12], uuid[11], uuid[10], uuid[9], uuid[8], uuid[7], uuid[6], uuid[5], uuid[4], uuid[3], uuid[2], uuid[1], uuid[0]);

If you're going to do this multiple times, you should probably do the following:

#define UUID_FMT "%02x%02x%02x%02x-%02x%02x-%02x%02x-%02x%02x-%02x%02x%02x%02x%02x%02x"
#define UUID_PARAM(uuid) uuid[15], uuid[14], uuid[13], uuid[12], uuid[11], uuid[10], uuid[9], uuid[8], uuid[7], uuid[6], uuid[5], uuid[4], uuid[3], uuid[2], uuid[1], uuid[0]
ESP_LOGD(TAG, "  Service " UUID_FMT, UUID_PARAM(service_uuid));

I think (and hope) you'll find that they will match. Let me know if not...

Good day!

bilogic commented 5 years ago

Ohh.. ok let me try thanks!

bilogic commented 5 years ago

Ok, it works. I will open another issue for my actual problem. Thank you.