bleak
bleak copied to clipboard
Published
20 hours ago •
hbldh
hbldh
TimeoutError and EOFerror on connection with BleakClient
trafficstars
- bleak version: 0.19.5
- Python version: 3.11.0
- Operating System: Debian GNU/Linux 11 (bullseye) (raspberry pi 4b)
- BlueZ version (
bluetoothctl -v) in case of Linux: 5.55
Description
I'm trying to make a UART connection over bluetooth between a raspberry pi 4b (client), and an ESP-WROOM-32 running micropython.
What I Did
This has produced many different errors and everytime i resolve one another one seems to come up. Initially the raspberry pi would disconnect immidiately upon connecting. This both happened when called from python through bleak and directly through bluetoothctl, and may thus have been either a driver or chip failure unrelated to Bleak. This was resolved by switching to a USB bluetooth dongle and disabling the onboard bluetooth. Now I was able to connect through bluetoothctl, but with bleak I would alternate between the Asyncio timeout and EOFerror shown below. In the bluetoothctl cli i can see that when I run the bleak code, a connection is sometimes established, but it usually drops after 10-15 seconds at which point I get the timeout error in Python.
Bleak managed to connect properly at one point, but after a reboot I was unable to reproduce this, and I have no idea why it worked that one time.
I've also managed to establish stable connections to the ESP32 using bleak from multiple windows machines, so it's unlikely that the ESP32 is causing the erros.
This is the minimal workable example of the code used:
import asyncio
from bleak import BleakClient
async def main():
async with BleakClient(08:3a:f2:a9:db:aa) as client:
print("connected")
asyncio.run(main())
Logs
I can't seem to reproduce the EOFerror anymore, but I know it was very similar to the one found in this issue: https://github.com/hbldh/bleak/issues/409
Timeout error:
Traceback (most recent call last):
File "/home/glove/.local/lib/python3.11/site-packages/bleak/backends/bluezdbus/client.py", line 172, in connect
reply = await self._bus.call(
^^^^^^^^^^^^^^^^^^^^^
File "/home/glove/.local/lib/python3.11/site-packages/dbus_fast/aio/message_bus.py", line 370, in call
await future
asyncio.exceptions.CancelledError
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/home/glove/P3s/trouble.py", line 13, in <module>
asyncio.run(main())
File "/usr/local/lib/python3.11/asyncio/runners.py", line 190, in run
return runner.run(main)
^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.11/asyncio/runners.py", line 118, in run
return self._loop.run_until_complete(task)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.11/asyncio/base_events.py", line 650, in run_until_complete
return future.result()
^^^^^^^^^^^^^^^
File "/home/glove/P3s/trouble.py", line 9, in main
async with BleakClient(mac) as client:
File "/home/glove/.local/lib/python3.11/site-packages/bleak/__init__.py", line 433, in __aenter__
await self.connect()
File "/home/glove/.local/lib/python3.11/site-packages/bleak/__init__.py", line 471, in connect
return await self._backend.connect(**kwargs)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/home/glove/.local/lib/python3.11/site-packages/bleak/backends/bluezdbus/client.py", line 171, in connect
async with async_timeout.timeout(timeout):
File "/home/glove/.local/lib/python3.11/site-packages/async_timeout/__init__.py", line 129, in __aexit__
self._do_exit(exc_type)
File "/home/glove/.local/lib/python3.11/site-packages/async_timeout/__init__.py", line 212, in _do_exit
raise asyncio.TimeoutError
TimeoutError
If BlueZ disconnects from a device early, it is usually because of a poorly configured device that is sending unexpected responses. You can log Bluetooth packets using hcidump and view them in Wireshark to see what is going on under the hood.
That hypothesis was what caused me to switch to USB dongle, but I figured that was due to an error (or faulty configuration) on the onboard chip. In that case It also seems weird that it behaves normally when using the UWP backend.
The hcidump doesn't say all that much, though maybe I'm missing something.
No. Time Source Destination Protocol Length Info
1 0.000000 controller host HCI_EVT 7 Rcvd Command Complete (LE Set Random Address)
Frame 1: 7 bytes on wire (56 bits), 7 bytes captured (56 bits)
Encapsulation type: Bluetooth H4 with linux header (99)
Arrival Time: Nov 28, 2022 18:31:13.119269000 Romance Standard Time
[Time shift for this packet: 0.000000000 seconds]
Epoch Time: 1669656673.119269000 seconds
[Time delta from previous captured frame: 0.000000000 seconds]
[Time delta from previous displayed frame: 0.000000000 seconds]
[Time since reference or first frame: 0.000000000 seconds]
Frame Number: 1
Frame Length: 7 bytes (56 bits)
Capture Length: 7 bytes (56 bits)
[Frame is marked: False]
[Frame is ignored: False]
Point-to-Point Direction: Received (1)
[Protocols in frame: bluetooth:hci_h4:bthci_evt]
Bluetooth
[Source: controller]
[Destination: host]
Bluetooth HCI H4
[Direction: Rcvd (0x01)]
HCI Packet Type: HCI Event (0x04)
Bluetooth HCI Event - Command Complete
Event Code: Command Complete (0x0e)
Parameter Total Length: 4
Number of Allowed Command Packets: 1
Command Opcode: LE Set Random Address (0x2005)
0010 00.. .... .... = Opcode Group Field: LE Controller Commands (0x08)
.... ..00 0000 0101 = Opcode Command Field: LE Set Random Address (0x005)
Status: Success (0x00)
No. Time Source Destination Protocol Length Info
2 0.002997 controller host HCI_EVT 7 Rcvd Command Complete (LE Set Scan Parameters)
Frame 2: 7 bytes on wire (56 bits), 7 bytes captured (56 bits)
Encapsulation type: Bluetooth H4 with linux header (99)
Arrival Time: Nov 28, 2022 18:31:13.122266000 Romance Standard Time
[Time shift for this packet: 0.000000000 seconds]
Epoch Time: 1669656673.122266000 seconds
[Time delta from previous captured frame: 0.002997000 seconds]
[Time delta from previous displayed frame: 0.002997000 seconds]
[Time since reference or first frame: 0.002997000 seconds]
Frame Number: 2
Frame Length: 7 bytes (56 bits)
Capture Length: 7 bytes (56 bits)
[Frame is marked: False]
[Frame is ignored: False]
Point-to-Point Direction: Received (1)
[Protocols in frame: bluetooth:hci_h4:bthci_evt]
Bluetooth
[Source: controller]
[Destination: host]
Bluetooth HCI H4
[Direction: Rcvd (0x01)]
HCI Packet Type: HCI Event (0x04)
Bluetooth HCI Event - Command Complete
Event Code: Command Complete (0x0e)
Parameter Total Length: 4
Number of Allowed Command Packets: 1
Command Opcode: LE Set Scan Parameters (0x200b)
0010 00.. .... .... = Opcode Group Field: LE Controller Commands (0x08)
.... ..00 0000 1011 = Opcode Command Field: LE Set Scan Parameters (0x00b)
Status: Success (0x00)
No. Time Source Destination Protocol Length Info
3 0.005998 controller host HCI_EVT 7 Rcvd Command Complete (LE Set Scan Enable)
Frame 3: 7 bytes on wire (56 bits), 7 bytes captured (56 bits)
Encapsulation type: Bluetooth H4 with linux header (99)
Arrival Time: Nov 28, 2022 18:31:13.125267000 Romance Standard Time
[Time shift for this packet: 0.000000000 seconds]
Epoch Time: 1669656673.125267000 seconds
[Time delta from previous captured frame: 0.003001000 seconds]
[Time delta from previous displayed frame: 0.003001000 seconds]
[Time since reference or first frame: 0.005998000 seconds]
Frame Number: 3
Frame Length: 7 bytes (56 bits)
Capture Length: 7 bytes (56 bits)
[Frame is marked: False]
[Frame is ignored: False]
Point-to-Point Direction: Received (1)
[Protocols in frame: bluetooth:hci_h4:bthci_evt]
Bluetooth
[Source: controller]
[Destination: host]
Bluetooth HCI H4
[Direction: Rcvd (0x01)]
HCI Packet Type: HCI Event (0x04)
Bluetooth HCI Event - Command Complete
Event Code: Command Complete (0x0e)
Parameter Total Length: 4
Number of Allowed Command Packets: 1
Command Opcode: LE Set Scan Enable (0x200c)
0010 00.. .... .... = Opcode Group Field: LE Controller Commands (0x08)
.... ..00 0000 1100 = Opcode Command Field: LE Set Scan Enable (0x00c)
Status: Success (0x00)
No. Time Source Destination Protocol Length Info
4 0.245044 controller host HCI_EVT 7 Rcvd Command Complete (LE Set Scan Enable)
Frame 4: 7 bytes on wire (56 bits), 7 bytes captured (56 bits)
Encapsulation type: Bluetooth H4 with linux header (99)
Arrival Time: Nov 28, 2022 18:31:13.364313000 Romance Standard Time
[Time shift for this packet: 0.000000000 seconds]
Epoch Time: 1669656673.364313000 seconds
[Time delta from previous captured frame: 0.239046000 seconds]
[Time delta from previous displayed frame: 0.239046000 seconds]
[Time since reference or first frame: 0.245044000 seconds]
Frame Number: 4
Frame Length: 7 bytes (56 bits)
Capture Length: 7 bytes (56 bits)
[Frame is marked: False]
[Frame is ignored: False]
Point-to-Point Direction: Received (1)
[Protocols in frame: bluetooth:hci_h4:bthci_evt]
Bluetooth
[Source: controller]
[Destination: host]
Bluetooth HCI H4
[Direction: Rcvd (0x01)]
HCI Packet Type: HCI Event (0x04)
Bluetooth HCI Event - Command Complete
Event Code: Command Complete (0x0e)
Parameter Total Length: 4
Number of Allowed Command Packets: 1
Command Opcode: LE Set Scan Enable (0x200c)
0010 00.. .... .... = Opcode Group Field: LE Controller Commands (0x08)
.... ..00 0000 1100 = Opcode Command Field: LE Set Scan Enable (0x00c)
Status: Success (0x00)
No. Time Source Destination Protocol Length Info
5 0.260104 controller host HCI_EVT 7 Rcvd Command Status (Create Connection)
Frame 5: 7 bytes on wire (56 bits), 7 bytes captured (56 bits)
Encapsulation type: Bluetooth H4 with linux header (99)
Arrival Time: Nov 28, 2022 18:31:13.379373000 Romance Standard Time
[Time shift for this packet: 0.000000000 seconds]
Epoch Time: 1669656673.379373000 seconds
[Time delta from previous captured frame: 0.015060000 seconds]
[Time delta from previous displayed frame: 0.015060000 seconds]
[Time since reference or first frame: 0.260104000 seconds]
Frame Number: 5
Frame Length: 7 bytes (56 bits)
Capture Length: 7 bytes (56 bits)
[Frame is marked: False]
[Frame is ignored: False]
Point-to-Point Direction: Received (1)
[Protocols in frame: bluetooth:hci_h4:bthci_evt]
Bluetooth
[Source: controller]
[Destination: host]
Bluetooth HCI H4
[Direction: Rcvd (0x01)]
HCI Packet Type: HCI Event (0x04)
Bluetooth HCI Event - Command Status
Event Code: Command Status (0x0f)
Parameter Total Length: 4
Status: Pending (0x00)
Number of Allowed Command Packets: 1
Command Opcode: Create Connection (0x0405)
0000 01.. .... .... = Opcode Group Field: Link Control Commands (0x01)
.... ..00 0000 0101 = Opcode Command Field: Create Connection (0x005)
No. Time Source Destination Protocol Length Info
6 5.379801 controller host HCI_EVT 14 Rcvd Connect Complete
Frame 6: 14 bytes on wire (112 bits), 14 bytes captured (112 bits)
Encapsulation type: Bluetooth H4 with linux header (99)
Arrival Time: Nov 28, 2022 18:31:18.499070000 Romance Standard Time
[Time shift for this packet: 0.000000000 seconds]
Epoch Time: 1669656678.499070000 seconds
[Time delta from previous captured frame: 5.119697000 seconds]
[Time delta from previous displayed frame: 5.119697000 seconds]
[Time since reference or first frame: 5.379801000 seconds]
Frame Number: 6
Frame Length: 14 bytes (112 bits)
Capture Length: 14 bytes (112 bits)
[Frame is marked: False]
[Frame is ignored: False]
Point-to-Point Direction: Received (1)
[Protocols in frame: bluetooth:hci_h4:bthci_evt]
Bluetooth
[Source: controller]
[Destination: host]
Bluetooth HCI H4
[Direction: Rcvd (0x01)]
HCI Packet Type: HCI Event (0x04)
Bluetooth HCI Event - Connect Complete
Event Code: Connect Complete (0x03)
Parameter Total Length: 11
Status: Page Timeout (0x04)
Connection Handle: 0x0080
BD_ADDR: Espressi_a9:db:aa (08:3a:f2:a9:db:aa)
Link Type: ACL connection (Data Channels) (0x01)
Encryption Mode: Encryption Disabled (0x00)
No. Time Source Destination Protocol Length Info
7 5.410788 controller host HCI_EVT 7 Rcvd Command Complete (LE Set Scan Parameters)
Frame 7: 7 bytes on wire (56 bits), 7 bytes captured (56 bits)
Encapsulation type: Bluetooth H4 with linux header (99)
Arrival Time: Nov 28, 2022 18:31:18.530057000 Romance Standard Time
[Time shift for this packet: 0.000000000 seconds]
Epoch Time: 1669656678.530057000 seconds
[Time delta from previous captured frame: 0.030987000 seconds]
[Time delta from previous displayed frame: 0.030987000 seconds]
[Time since reference or first frame: 5.410788000 seconds]
Frame Number: 7
Frame Length: 7 bytes (56 bits)
Capture Length: 7 bytes (56 bits)
[Frame is marked: False]
[Frame is ignored: False]
Point-to-Point Direction: Received (1)
[Protocols in frame: bluetooth:hci_h4:bthci_evt]
Bluetooth
[Source: controller]
[Destination: host]
Bluetooth HCI H4
[Direction: Rcvd (0x01)]
HCI Packet Type: HCI Event (0x04)
Bluetooth HCI Event - Command Complete
Event Code: Command Complete (0x0e)
Parameter Total Length: 4
Number of Allowed Command Packets: 1
Command Opcode: LE Set Scan Parameters (0x200b)
0010 00.. .... .... = Opcode Group Field: LE Controller Commands (0x08)
.... ..00 0000 1011 = Opcode Command Field: LE Set Scan Parameters (0x00b)
Status: Success (0x00)
No. Time Source Destination Protocol Length Info
8 5.413778 controller host HCI_EVT 7 Rcvd Command Complete (LE Set Scan Enable)
Frame 8: 7 bytes on wire (56 bits), 7 bytes captured (56 bits)
Encapsulation type: Bluetooth H4 with linux header (99)
Arrival Time: Nov 28, 2022 18:31:18.533047000 Romance Standard Time
[Time shift for this packet: 0.000000000 seconds]
Epoch Time: 1669656678.533047000 seconds
[Time delta from previous captured frame: 0.002990000 seconds]
[Time delta from previous displayed frame: 0.002990000 seconds]
[Time since reference or first frame: 5.413778000 seconds]
Frame Number: 8
Frame Length: 7 bytes (56 bits)
Capture Length: 7 bytes (56 bits)
[Frame is marked: False]
[Frame is ignored: False]
Point-to-Point Direction: Received (1)
[Protocols in frame: bluetooth:hci_h4:bthci_evt]
Bluetooth
[Source: controller]
[Destination: host]
Bluetooth HCI H4
[Direction: Rcvd (0x01)]
HCI Packet Type: HCI Event (0x04)
Bluetooth HCI Event - Command Complete
Event Code: Command Complete (0x0e)
Parameter Total Length: 4
Number of Allowed Command Packets: 1
Command Opcode: LE Set Scan Enable (0x200c)
0010 00.. .... .... = Opcode Group Field: LE Controller Commands (0x08)
.... ..00 0000 1100 = Opcode Command Field: LE Set Scan Enable (0x00c)
Status: Success (0x00)
No. Time Source Destination Protocol Length Info
9 5.704813 controller host HCI_EVT 7 Rcvd Command Complete (LE Set Scan Enable)
Frame 9: 7 bytes on wire (56 bits), 7 bytes captured (56 bits)
Encapsulation type: Bluetooth H4 with linux header (99)
Arrival Time: Nov 28, 2022 18:31:18.824082000 Romance Standard Time
[Time shift for this packet: 0.000000000 seconds]
Epoch Time: 1669656678.824082000 seconds
[Time delta from previous captured frame: 0.291035000 seconds]
[Time delta from previous displayed frame: 0.291035000 seconds]
[Time since reference or first frame: 5.704813000 seconds]
Frame Number: 9
Frame Length: 7 bytes (56 bits)
Capture Length: 7 bytes (56 bits)
[Frame is marked: False]
[Frame is ignored: False]
Point-to-Point Direction: Received (1)
[Protocols in frame: bluetooth:hci_h4:bthci_evt]
Bluetooth
[Source: controller]
[Destination: host]
Bluetooth HCI H4
[Direction: Rcvd (0x01)]
HCI Packet Type: HCI Event (0x04)
Bluetooth HCI Event - Command Complete
Event Code: Command Complete (0x0e)
Parameter Total Length: 4
Number of Allowed Command Packets: 1
Command Opcode: LE Set Scan Enable (0x200c)
0010 00.. .... .... = Opcode Group Field: LE Controller Commands (0x08)
.... ..00 0000 1100 = Opcode Command Field: LE Set Scan Enable (0x00c)
Status: Success (0x00)
No. Time Source Destination Protocol Length Info
10 5.707812 controller host HCI_EVT 7 Rcvd Command Status (LE Create Connection)
Frame 10: 7 bytes on wire (56 bits), 7 bytes captured (56 bits)
Encapsulation type: Bluetooth H4 with linux header (99)
Arrival Time: Nov 28, 2022 18:31:18.827081000 Romance Standard Time
[Time shift for this packet: 0.000000000 seconds]
Epoch Time: 1669656678.827081000 seconds
[Time delta from previous captured frame: 0.002999000 seconds]
[Time delta from previous displayed frame: 0.002999000 seconds]
[Time since reference or first frame: 5.707812000 seconds]
Frame Number: 10
Frame Length: 7 bytes (56 bits)
Capture Length: 7 bytes (56 bits)
[Frame is marked: False]
[Frame is ignored: False]
Point-to-Point Direction: Received (1)
[Protocols in frame: bluetooth:hci_h4:bthci_evt]
Bluetooth
[Source: controller]
[Destination: host]
Bluetooth HCI H4
[Direction: Rcvd (0x01)]
HCI Packet Type: HCI Event (0x04)
Bluetooth HCI Event - Command Status
Event Code: Command Status (0x0f)
Parameter Total Length: 4
Status: Pending (0x00)
Number of Allowed Command Packets: 1
Command Opcode: LE Create Connection (0x200d)
0010 00.. .... .... = Opcode Group Field: LE Controller Commands (0x08)
.... ..00 0000 1101 = Opcode Command Field: LE Create Connection (0x00d)
No. Time Source Destination Protocol Length Info
11 7.238060 controller host HCI_EVT 7 Rcvd Command Status (LE Read Remote Features)
Frame 11: 7 bytes on wire (56 bits), 7 bytes captured (56 bits)
Encapsulation type: Bluetooth H4 with linux header (99)
Arrival Time: Nov 28, 2022 18:31:20.357329000 Romance Standard Time
[Time shift for this packet: 0.000000000 seconds]
Epoch Time: 1669656680.357329000 seconds
[Time delta from previous captured frame: 1.530248000 seconds]
[Time delta from previous displayed frame: 1.530248000 seconds]
[Time since reference or first frame: 7.238060000 seconds]
Frame Number: 11
Frame Length: 7 bytes (56 bits)
Capture Length: 7 bytes (56 bits)
[Frame is marked: False]
[Frame is ignored: False]
Point-to-Point Direction: Received (1)
[Protocols in frame: bluetooth:hci_h4:bthci_evt]
Bluetooth
[Source: controller]
[Destination: host]
Bluetooth HCI H4
[Direction: Rcvd (0x01)]
HCI Packet Type: HCI Event (0x04)
Bluetooth HCI Event - Command Status
Event Code: Command Status (0x0f)
Parameter Total Length: 4
Status: Pending (0x00)
Number of Allowed Command Packets: 1
Command Opcode: LE Read Remote Features (0x2016)
0010 00.. .... .... = Opcode Group Field: LE Controller Commands (0x08)
.... ..00 0001 0110 = Opcode Command Field: LE Read Remote Features (0x016)
No. Time Source Destination Protocol Length Info
12 23.003253 controller host HCI_EVT 7 Rcvd Command Status (Disconnect)
Frame 12: 7 bytes on wire (56 bits), 7 bytes captured (56 bits)
Encapsulation type: Bluetooth H4 with linux header (99)
Arrival Time: Nov 28, 2022 18:31:36.122522000 Romance Standard Time
[Time shift for this packet: 0.000000000 seconds]
Epoch Time: 1669656696.122522000 seconds
[Time delta from previous captured frame: 15.765193000 seconds]
[Time delta from previous displayed frame: 15.765193000 seconds]
[Time since reference or first frame: 23.003253000 seconds]
Frame Number: 12
Frame Length: 7 bytes (56 bits)
Capture Length: 7 bytes (56 bits)
[Frame is marked: False]
[Frame is ignored: False]
Point-to-Point Direction: Received (1)
[Protocols in frame: bluetooth:hci_h4:bthci_evt]
Bluetooth
[Source: controller]
[Destination: host]
Bluetooth HCI H4
[Direction: Rcvd (0x01)]
HCI Packet Type: HCI Event (0x04)
Bluetooth HCI Event - Command Status
Event Code: Command Status (0x0f)
Parameter Total Length: 4
Status: Pending (0x00)
Number of Allowed Command Packets: 1
Command Opcode: Disconnect (0x0406)
0000 01.. .... .... = Opcode Group Field: Link Control Commands (0x01)
.... ..00 0000 0110 = Opcode Command Field: Disconnect (0x006)
No. Time Source Destination Protocol Length Info
13 23.011257 controller host HCI_EVT 7 Rcvd Disconnect Complete
Frame 13: 7 bytes on wire (56 bits), 7 bytes captured (56 bits)
Encapsulation type: Bluetooth H4 with linux header (99)
Arrival Time: Nov 28, 2022 18:31:36.130526000 Romance Standard Time
[Time shift for this packet: 0.000000000 seconds]
Epoch Time: 1669656696.130526000 seconds
[Time delta from previous captured frame: 0.008004000 seconds]
[Time delta from previous displayed frame: 0.008004000 seconds]
[Time since reference or first frame: 23.011257000 seconds]
Frame Number: 13
Frame Length: 7 bytes (56 bits)
Capture Length: 7 bytes (56 bits)
[Frame is marked: False]
[Frame is ignored: False]
Point-to-Point Direction: Received (1)
[Protocols in frame: bluetooth:hci_h4:bthci_evt]
Bluetooth
[Source: controller]
[Destination: host]
Bluetooth HCI H4
[Direction: Rcvd (0x01)]
HCI Packet Type: HCI Event (0x04)
Bluetooth HCI Event - Disconnect Complete
Event Code: Disconnect Complete (0x05)
Parameter Total Length: 4
Status: Success (0x00)
Connection Handle: 0x0000
Reason: Connection Terminated by Local Host (0x16)
but I figured that was due to an error (or faulty configuration) on the onboard chip. In that case It also seems weird that it behaves normally when using the UWP backend.
BlueZ seems to be less forgiving that other Bluetooth stacks on other OSes.
In the logs, it looks like the device never responds to the "LE Read Remote Features" request.
Do you know what the response to this reqeust should be? I can see on the ESP32 that the the last event before disconnect is the MTU exchange (Though I'm unsure if it's completed)
Do you know what the response to this reqeust should be?
a "LE Read Remote Features" response.
@Creich21 I had a similar issue when using esp-at and needed to change oscillator to fix it
https://github.com/espressif/esp-at/issues/659
