[BLE Client] Deadlock when calling writeValue after registerForNotify

[console-netsphere]

Describe your system
Hardware: Custom ESP32 Module
Computer: Windows 10
Core version: 1.0.4
Environment: Arduino IDE

Hardware:

Board: ESP32 Dev Module
Core Installation version: 1.04
IDE name: Arduino IDE
Flash Frequency: 40Mhz
PSRAM enabled: no
Upload Speed: 115200
Computer OS: Windows 10

Description:

My task locks when calling writeValue right after calling registerForNotify.
This is very random and seems to happen most frequently when the client disconnects from the sever and reconnects, and then again tries to register for notifications from server and write a value in the characteristic.
I got from the logs that when calling writeValue it waits forever for a mutex to be released:
m_semaphoreWriteCharEvt.take("writeValue");
It seems that registerForNotify take the writeValue mutex and never releases it, probably waiting for an event release it.
When writeValue is called, it tries to take the mutex and keep waiting forever causing the deadlock.
As a temporary solution I set a task watchdog to panic and reset the device if the situation above happen, but this may be affecting other people projects that a reset is impracticable.
Also, the client is connected and the code is executed right after a scan and successful connection to server.

Sketch:

bool WeAcessBLEClient::elevateConnectionStatus(notify_callback response_callback){

	LOG_MSG("[Info] Informing server that the device is a permanent provider...");

	if(!isClientConnected()){
		LOG_MSG("[Error] We are not connected, or the client is NULL");
		return false;
	}

	/* First we get the tag service */
	BLERemoteService *tag_serv =
			bleClient->getService(TAG_SERVICE);
	if(!tag_serv){
		LOG_MSG("[Error] Could not get service for TAGs");
		return false;
	}


	/* Then we write the permanent provider key in the related characteristic */
	BLERemoteCharacteristic *perm_char =
			tag_serv->getCharacteristic(PERM_TAG_PROVIDER_CHARACT);
	if(!perm_char){
		LOG_MSG("[Error] Could not get characteristic for permanent TAG provider.");
		return false;
	}

	/*Register to grab authentication status from server */
	perm_char->registerForNotify(response_callback);
	delay(100);
	LOG_MSG("Registered to server notifications!");
	/* At last We send the permanent provider key to server */
      *** LOCKS IN THE LINE BELOW ****
	perm_char->writeValue(BLE_PERM_CONN_PWD.c_str());
	LOG_MSG("[Info] Registering in server as a permanent provider...");
	return true;
}

Logs

[Info] Found paired device...
[V][BLEScan.cpp:250] stop(): >> stop()
[V][FreeRTOS.cpp:143] give(): Semaphore giving: name: ScanEnd (0x3ffdf884), owner: start
[V][BLEScan.cpp:262] stop(): << stop()
[V][FreeRTOS.cpp:77] wait(): << wait: Semaphore released: name: ScanEnd (0x3ffdf884), owner: <N/A>
[V][BLEUtils.cpp:1817] gapEventToString(): gapEventToString: Unknown event type 3 0x03
[V][BLEUtils.cpp:1049] dumpGapEvent(): Received a GAP event: Unknown event type
[V][BLEUtils.cpp:1264] dumpGapEvent(): *** dumpGapEvent: Logger not coded ***
[D][BLEClient.cpp:457] handleGAPEvent(): BLEClient ... handling GAP event!
[V][BLEClient.cpp:96] connect(): >> connect(a4:cf:12:45:34:2e)
[V][BLEUtils.cpp:1817] gapEventToString(): gapEventToString: Unknown event type 3 0x03
[I][BLEDevice.cpp:593] addPeerDevice(): add conn_id: 25, GATT role: client
[V][BLEUtils.cpp:1049] dumpGapEvent(): Received a GAP event: Unknown event type
[D][FreeRTOS.cpp:189] take(): Semaphore taking: name: RegEvt (0x3ffdfbf8), owner: <N/A> for connect
[V][BLEUtils.cpp:1264] dumpGapEvent(): *** dumpGapEvent: Logger not coded ***
[D][FreeRTOS.cpp:198] take(): Semaphore taken:  name: RegEvt (0x3ffdfbf8), owner: connect
[D][BLEClient.cpp:457] handleGAPEvent(): BLEClient ... handling GAP event!
[V][FreeRTOS.cpp:63] wait(): >> wait: Semaphore waiting: name: RegEvt (0x3ffdfbf8), owner: connect for connect
[V][BLEUtils.cpp:1817] gapEventToString(): gapEventToString: Unknown event type 3 0x03
[V][BLEUtils.cpp:1049] dumpGapEvent(): Received a GAP event: Unknown event type
[V][BLEUtils.cpp:1264] dumpGapEvent(): *** dumpGapEvent: Logger not coded ***
[D][BLEClient.cpp:457] handleGAPEvent(): BLEClient ... handling GAP event!
[V][BLEUtils.cpp:1817] gapEventToString(): gapEventToString: Unknown event type 3 0x03
[V][BLEUtils.cpp:1049] dumpGapEvent(): Received a GAP event: Unknown event type
[V][BLEUtils.cpp:1264] dumpGapEvent(): *** dumpGapEvent: Logger not coded ***
[D][BLEClient.cpp:457] handleGAPEvent(): BLEClient ... handling GAP event!
[V][BLEUtils.cpp:1817] gapEventToString(): gapEventToString: Unknown event type 3 0x03
[V][BLEUtils.cpp:1049] dumpGapEvent(): Received a GAP event: Unknown event type
[V][BLEUtils.cpp:1264] dumpGapEvent(): *** dumpGapEvent: Logger not coded ***
[D][BLEClient.cpp:457] handleGAPEvent(): BLEClient ... handling GAP event!
[V][BLEUtils.cpp:1817] gapEventToString(): gapEventToString: Unknown event type 3 0x03
[V][BLEUtils.cpp:1049] dumpGapEvent(): Received a GAP event: Unknown event type
[V][BLEUtils.cpp:1264] dumpGapEvent(): *** dumpGapEvent: Logger not coded ***
[D][BLEClient.cpp:457] handleGAPEvent(): BLEClient ... handling GAP event!
[V][BLEUtils.cpp:1817] gapEventToString(): gapEventToString: Unknown event type 3 0x03
[V][BLEUtils.cpp:1049] dumpGapEvent(): Received a GAP event: Unknown event type
[V][BLEUtils.cpp:1264] dumpGapEvent(): *** dumpGapEvent: Logger not coded ***
[D][BLEClient.cpp:457] handleGAPEvent(): BLEClient ... handling GAP event!
[V][BLEUtils.cpp:1817] gapEventToString(): gapEventToString: Unknown event type 3 0x03
[V][BLEUtils.cpp:1049] dumpGapEvent(): Received a GAP event: Unknown event type
[V][BLEUtils.cpp:1264] dumpGapEvent(): *** dumpGapEvent: Logger not coded ***
[D][BLEClient.cpp:457] handleGAPEvent(): BLEClient ... handling GAP event!
[V][BLEUtils.cpp:1817] gapEventToString(): gapEventToString: Unknown event type 3 0x03
[V][BLEUtils.cpp:1049] dumpGapEvent(): Received a GAP event: Unknown event type
[V][BLEUtils.cpp:1264] dumpGapEvent(): *** dumpGapEvent: Logger not coded ***
[D][BLEClient.cpp:457] handleGAPEvent(): BLEClient ... handling GAP event!
[V][BLEUtils.cpp:1817] gapEventToString(): gapEventToString: Unknown event type 3 0x03
[V][BLEUtils.cpp:1049] dumpGapEvent(): Received a GAP event: Unknown event type
[V][BLEUtils.cpp:1264] dumpGapEvent(): *** dumpGapEvent: Logger not coded ***
[D][BLEClient.cpp:457] handleGAPEvent(): BLEClient ... handling GAP event!
[V][BLEUtils.cpp:1817] gapEventToString(): gapEventToString: Unknown event type 3 0x03
[V][BLEUtils.cpp:1049] dumpGapEvent(): Received a GAP event: Unknown event type
[V][BLEUtils.cpp:1264] dumpGapEvent(): *** dumpGapEvent: Logger not coded ***
[D][BLEClient.cpp:457] handleGAPEvent(): BLEClient ... handling GAP event!
[V][BLEUtils.cpp:1817] gapEventToString(): gapEventToString: Unknown event type 3 0x03
[V][BLEUtils.cpp:1049] dumpGapEvent(): Received a GAP event: Unknown event type
[V][BLEUtils.cpp:1264] dumpGapEvent(): *** dumpGapEvent: Logger not coded ***
[D][BLEClient.cpp:457] handleGAPEvent(): BLEClient ... handling GAP event!
[V][BLEUtils.cpp:1817] gapEventToString(): gapEventToString: Unknown event type 18 0x12
[V][BLEUtils.cpp:1049] dumpGapEvent(): Received a GAP event: Unknown event type
[V][BLEUtils.cpp:1264] dumpGapEvent(): *** dumpGapEvent: Logger not coded ***
[D][BLEClient.cpp:457] handleGAPEvent(): BLEClient ... handling GAP event!
[V][BLEUtils.cpp:951] gattClientEventTypeToString(): Unknown GATT Client event type: 0
[D][BLEDevice.cpp:148] gattClientEventHandler(): gattClientEventHandler [esp_gatt_if: 4] ... Unknown
[V][BLEUtils.cpp:951] gattClientEventTypeToString(): Unknown GATT Client event type: 0
[V][BLEUtils.cpp:1283] dumpGattClientEvent(): GATT Event: Unknown
[V][BLEUtils.cpp:951] gattClientEventTypeToString(): Unknown GATT Client event type: 0
[D][BLEClient.cpp:158] gattClientEventHandler(): gattClientEventHandler [esp_gatt_if: 4] ... Unknown
[V][FreeRTOS.cpp:143] give(): Semaphore giving: name: RegEvt (0x3ffdfbf8), owner: connect
[V][FreeRTOS.cpp:77] wait(): << wait: Semaphore released: name: RegEvt (0x3ffdfbf8), owner: <N/A>
[D][FreeRTOS.cpp:189] take(): Semaphore taking: name: OpenEvt (0x3ffdfc58), owner: <N/A> for connect
[D][FreeRTOS.cpp:198] take(): Semaphore taken:  name: OpenEvt (0x3ffdfc58), owner: connect
[V][FreeRTOS.cpp:63] wait(): >> wait: Semaphore waiting: name: OpenEvt (0x3ffdfc58), owner: connect for connect
2021/03/15 22:37:52: [V][BLEUtils.cpp:951] gattClientEventTypeToString(): Unknown GATT Client event type: 40
[D][BLEDevice.cpp:148] gattClientEventHandler(): gattClientEventHandler [esp_gatt_if: 4] ... Unknown
[V][BLEUtils.cpp:951] gattClientEventTypeToString(): Unknown GATT Client event type: 40
[V][BLEUtils.cpp:1283] dumpGattClientEvent(): GATT Event: Unknown
[V][BLEUtils.cpp:951] gattClientEventTypeToString(): Unknown GATT Client event type: 40
[D][BLEClient.cpp:158] gattClientEventHandler(): gattClientEventHandler [esp_gatt_if: 4] ... Unknown
[D][BLEDevice.cpp:577] updatePeerDevice(): update conn_id: 4, GATT role: client
[V][BLEUtils.cpp:951] gattClientEventTypeToString(): Unknown GATT Client event type: 2
[D][BLEDevice.cpp:148] gattClientEventHandler(): gattClientEventHandler [esp_gatt_if: 4] ... Unknown
[V][BLEUtils.cpp:951] gattClientEventTypeToString(): Unknown GATT Client event type: 2
[V][BLEUtils.cpp:1283] dumpGattClientEvent(): GATT Event: Unknown
[V][BLEUtils.cpp:951] gattClientEventTypeToString(): Unknown GATT Client event type: 2
[D][BLEClient.cpp:158] gattClientEventHandler(): gattClientEventHandler [esp_gatt_if: 4] ... Unknown
[V][FreeRTOS.cpp:143] give(): Semaphore giving: name: OpenEvt (0x3ffdfc58), owner: connect
[V][FreeRTOS.cpp:77] wait(): << wait: Semaphore released: name: OpenEvt (0x3ffdfc58), owner: <N/A>
[V][BLEClient.cpp:129] connect(): << connect(), rc=1
[Info] Connected to target device at address a4:cf:12:45:34:2e
[DEBUG] Changing task WDT to 10 seconds!
[Info] Informing server that the device is a permanent provider...
[V][BLEClient.cpp:377] getService(): >> getService: uuid: 45b70d8c-19ee-414c-a31f-c4fa3ee3eaa0
[V][BLEClient.cpp:390] getService(): << getService: found the service with uuid: 45b70d8c-19ee-414c-a31f-c4fa3ee3eaa0
[V][BLERemoteCharacteristic.cpp:438] registerForNotify(): >> registerForNotify(): Characteristic: uuid: c3a2dcd7-6ec9-42da-a74f-b7dfb86a74cb, handle: 59 0x003b, props: broadcast: 0, read: 0, write_nr: 0, write: 1, notify: 1, indicate: 0, auth: 0
[D][FreeRTOS.cpp:189] take(): Semaphore taking: name: RegForNotifyEvt (0x3ffe23c0), owner: <N/A> for registerForNotify
[D][FreeRTOS.cpp:198] take(): Semaphore taken:  name: RegForNotifyEvt (0x3ffe23c0), owner: registerForNotify
[V][BLERemoteCharacteristic.cpp:323] getDescriptor(): >> getDescriptor: uuid: 00002902-0000-1000-8000-00805f9b34fb
[V][BLEUtils.cpp:951] gattClientEventTypeToString(): Unknown GATT Client event type: 38
[V][BLERemoteCharacteristic.cpp:327] getDescriptor(): << getDescriptor: found
[D][BLEDevice.cpp:148] gattClientEventHandler(): gattClientEventHandler [esp_gatt_if: 4] ... Unknown
[V][BLERemoteDescriptor.cpp:132] writeValue(): >> writeValue: handle: 60, uuid: 00002902-0000-1000-8000-00805f9b34fb
[V][BLEUtils.cpp:951] gattClientEventTypeToString(): Unknown GATT Client event type: 38
[V][BLERemoteDescriptor.cpp:151] writeValue(): << writeValue
[V][BLEUtils.cpp:1283] dumpGattClientEvent(): GATT Event: Unknown
[V][FreeRTOS.cpp:63] wait(): >> wait: Semaphore waiting: name: RegForNotifyEvt (0x3ffe23c0), owner: registerForNotify for registerForNotify
[V][BLEUtils.cpp:951] gattClientEventTypeToString(): Unknown GATT Client event type: 38
[D][BLEClient.cpp:158] gattClientEventHandler(): gattClientEventHandler [esp_gatt_if: 4] ... Unknown
[V][FreeRTOS.cpp:143] give(): Semaphore giving: name: RegForNotifyEvt (0x3ffe23c0), owner: registerForNotify
[V][FreeRTOS.cpp:77] wait(): << wait: Semaphore released: name: RegForNotifyEvt (0x3ffe23c0), owner: <N/A>
[V][BLERemoteCharacteristic.cpp:478] registerForNotify(): << registerForNotify()
Registered to server notifications!
[V][BLERemoteCharacteristic.cpp:549] writeValue(): >> writeValue(), length: 8
[D][FreeRTOS.cpp:189] take(): Semaphore taking: name: WriteCharEvt (0x3ffe2420), owner: <N/A> for writeValue
[D][FreeRTOS.cpp:198] take(): Semaphore taken:  name: WriteCharEvt (0x3ffe2420), owner: writeValue
[V][FreeRTOS.cpp:63] wait(): >> wait: Semaphore waiting: name: WriteCharEvt (0x3ffe2420), owner: writeValue for writeValue
[Info] HMI Task Received Command Connected!
2021/03/15 22:37:59: [V][BLEUtils.cpp:951] gattClientEventTypeToString(): Unknown GATT Client event type: 41
[D][BLEDevice.cpp:148] gattClientEventHandler(): gattClientEventHandler [esp_gatt_if: 4] ... Unknown
[V][BLEUtils.cpp:951] gattClientEventTypeToString(): Unknown GATT Client event type: 41
[V][BLEUtils.cpp:1283] dumpGattClientEvent(): GATT Event: Unknown
[V][BLEUtils.cpp:951] gattClientEventTypeToString(): Unknown GATT Client event type: 41
[D][BLEClient.cpp:158] gattClientEventHandler(): gattClientEventHandler [esp_gatt_if: 4] ... Unknown
[V][FreeRTOS.cpp:143] give(): Semaphore giving: name: OpenEvt (0x3ffdfc58), owner: <N/A>
[V][FreeRTOS.cpp:143] give(): Semaphore giving: name: RssiCmplEvt (0x3ffdfd18), owner: <N/A>
[V][FreeRTOS.cpp:143] give(): Semaphore giving: name: SearchCmplEvt (0x3ffdfcb8), owner: <N/A>
[I][BLEDevice.cpp:604] removePeerDevice(): remove: 25, GATT role client
[V][BLEUtils.cpp:951] gattClientEventTypeToString(): Unknown GATT Client event type: 5
[D][BLEDevice.cpp:148] gattClientEventHandler(): gattClientEventHandler [esp_gatt_if: 4] ... Unknown
[V][BLEUtils.cpp:951] gattClientEventTypeToString(): Unknown GATT Client event type: 5
[V][BLEUtils.cpp:1283] dumpGattClientEvent(): GATT Event: Unknown
[V][BLEUtils.cpp:951] gattClientEventTypeToString(): Unknown GATT Client event type: 1
[D][BLEDevice.cpp:148] gattClientEventHandler(): gattClientEventHandler [esp_gatt_if: 4] ... Unknown
[V][BLEUtils.cpp:951] gattClientEventTypeToString(): Unknown GATT Client event type: 1
[V][BLEUtils.cpp:1283] dumpGattClientEvent(): GATT Event: Unknown

[h2zero]

I really need to find my old code fixes for this library and PR them.

The issue here is your device has been disconnected while you were waiting for the write to complete and are now stuck on the semaphore as that event is not handled properly to release it in the BLERemoteChracteristic class.

Here is the fix; Add this code to this line:

case ESP_GATTC_DISCONNECT_EVT: {
        m_semaphoreWriteCharEvt.give(1);
	break;
}

That should resolve this issue.

[console-netsphere]

Thank you for providing the fix.
It would be nice to have this fix included in the next release.

[me-no-dev]

it will :)

[h2zero]

Nice :)

[ninja-]

nice