hbldh
'notification handler' invoked twice with same packet (issue observer only on 0.11.0 + 0.12.0)
- bleak version: 0.11.0 or 0.12.0
- Python version: 3.8.5
- Operating System: Debian 10 (Buster)
- BlueZ version (
bluetoothctl -v) in case of Linux: 5.54
Description
some times (~every 5 sessions) right after connection around fifth to10th packet 'data_notification_handler' invoked with same packet twice when actually client sent it once.
What I Did
connected client (NORDIC based) to RPI4 and rebooted client to initialize and reconnect. run BLE wireshark sniffer during the debug session for packet monitor.
# I have omitted the not interesting code
async def __start(self, loop):
self.lock = asyncio.Lock()
async with BleakClient(self.mac) as client:
self.client = client
self.disconnected_event = asyncio.Event()
def disconnect_callback(client):
loop.call_soon_threadsafe(self.disconnected_event.set)
client.set_disconnected_callback(disconnect_callback)
is_connected = await client.is_connected()
self.connected_event.set()
self.start_tpt_time = time.time()
await client.start_notify(NOTIFY_CHAR_UUID, self.data_notification_handler)
while True:
try:
if self.disconnected_event.is_set():
await self.on_disconnect(client)
return
if self.__was_closed and self.__target_ble_queue.empty():
self.log.info("BLE closing {}", self.mac)
return
data_packet = self.__target_ble_queue.get_nowait()
###########
total_length = len(data_packet.data)
bytes_sent = 0
while bytes_sent < total_length:
to_send = min(self.config.max_ble_packet_size_bytes - 8, total_length - bytes_sent)
content = data_packet.data[bytes_sent: bytes_sent + to_send]
padded_content = self.pad_packet(content)
await client.write_gatt_char(WRITE_CHAR_UUID, padded_content)
bytes_sent += to_send
#############
self.log.debug("write whole non padded packet {} with {} bytes via BLE done", data_packet.id, total_length)
except Empty:
await asyncio.sleep(0.5)
if not await client.is_connected():
error_message = "substrate {0} not connected".format(self.mac)
self.log.error(error_message)
raise Exception(error_message)
def data_notification_handler(self, sender, data):
try:
self.lock.acquire()
data_packet = DataPacket(bytearray(data[4:-4]))
self.__calculate_tpt(data)
self.__check_crc(data)
self.__check_index(data)
self.__target_tcp_queue.put_nowait(data_packet)
except Full:
first_msg = self.__target_tcp_queue.get()
self.__target_tcp_queue.put(DataPacket(bytearray(data[4:-4])))
except Exception as e:
import traceback
self.log.fatal("BLE data handler Exception :\n" + str(e) + str(traceback.format_exc()))
finally:
self.lock.release()
def __check_index(self, data: bytearray):
data_len = len(data)
if data_len > 8:
recv_index = struct.unpack_from("<I", data, 0)[0]
#self.log.fatal("index error computed = {}",recv_index)
if self.receive_index == -1:
self.receive_index = recv_index
else:
self.receive_index += 1
if self.receive_index != recv_index:
self.log.fatal("index error computed = {} actual = {}", self.receive_index, recv_index)
self.log.fatal("content of index error BLE packet \n{}\nlength {}", list(data), data_len)
self.receive_index = recv_index # align counter, wait for next failure
#raise Exception("wrong index")
else:
self.log.fatal("data packet size is {} less than 9.", data_len)
self.log.fatal("content short BLE packet \n{}\nlength {}", list(data), data_len)
raise Exception("data too short")
Output
Master (RPI4) log:
2021-06-27 16:26:13,734 - INFO - daemon - BleakClient trying to connect D1:9A:E6:FD:E4:37
2021-06-27 16:26:15,518 - INFO - daemon - substrate D1:9A:E6:FD:E4:37 Connected via BLE : True
2021-06-27 16:26:20,452 - CRITICAL - daemon - index error computed = 4 actual = 3
2021-06-27 16:26:20,453 - CRITICAL - daemon - content of index error BLE packet
[3, 0, 0, 0, 144, 0, 0, 0, 1, 0, 0, 0, 11, 199, 119, 155]
length 16
Please try logging D-Bus traffic as well (sudo dbus-monitor --system). I have seen a few time when other apps also connect to the device that BlueZ seems to send duplicate notifications. Restarting BlueZ fixed the issue in my case.
sudo dbus-monitor --system
note that with 0.8.0 and 0.10.0 there is no issue
Bluez log:
signal time=1625391870.076222 sender=:1.4 -> destination=(null destination) serial=2446 path=/org/bluez/hci0/dev_F0_47_F6_31_E2_B0/service0014/char0015; interface=org.freedesktop.DBus.Properties; member=PropertiesChanged
string "org.bluez.GattCharacteristic1"
array [
dict entry(
string "Value"
variant array of bytes [
05 00 00 00 90 00 00 00 01 00 00 00 eb 62 4a 74
]
)
]
array [
]
signal time=1625391870.076736 sender=:1.4 -> destination=(null destination) serial=2447 path=/org/bluez/hci0/dev_F0_47_F6_31_E2_B0/service0014/char0015; interface=org.freedesktop.DBus.Properties; member=PropertiesChanged
string "org.bluez.GattCharacteristic1"
array [
dict entry(
string "Value"
variant array of bytes [
05 00 00 00 90 00 00 00 01 00 00 00 eb 62 4a 74
]
)
]
array [
]
my log:
2021-07-04 09:44:30,055 - INFO - daemon - substrate F0:47:F6:31:E2:B0 Connected via BLE : True
2021-07-04 09:44:30,082 - DEBUG - daemon - content of BLE packet 3ee79283-0f1a-44c8-9fa1-fa67542db9c6
[144, 0, 0, 0, 1, 0, 0, 0]
length 8
2021-07-04 09:44:30,097 - DEBUG - daemon - content of BLE packet 6cfa26bc-67f8-4760-a254-27792f7ed334
[144, 0, 0, 0, 1, 0, 0, 0]
length 8
2021-07-04 09:44:30,099 - CRITICAL - daemon - index error computed = 6 actual = 5
2021-07-04 09:44:30,102 - CRITICAL - daemon - content of index error BLE packet
[5, 0, 0, 0, 144, 0, 0, 0, 1, 0, 0, 0, 235, 98, 74, 116]
length 16
It would be helpful to see a full D-Bus log starting with a fresh system reboot so we can see if Bleak is subscribing to the notification signal more than once in a session.