DBUS connection not closed properly in all cases

[koenvsteenb]

• bleak version: 0.22.2
• Python version: 3.11
• Operating System: Linux (BalenaOS 5.3.7)
• BlueZ version (bluetoothctl -v) in case of Linux: 5.66
• Docker base image: balenalib/aarch64-python:3.11

Description

Describe what you were trying to get done.
Tell us what happened, what went wrong, and what you expected to happen.

In our company we have a product which scans and reads bluetooth devices continuously. These devices run 24/7 and reboot every night. In some cases we would notice a peak in errors from a device; which would spam EOFError's each few seconds. Further inspection revealed a notice in the journalctl dbus-daemon[1688]: [system] The maximum number of active connections for UID 0 has been reached (max_connections_per_user=256). From what I could see, some dbus connections could not be closed. Some more inspection revealed that almost all of the connections originated in our python script.

What I Did

I tried to find the root cause by correlating with errors. What I found was that the about 240 errors originated from BlueZManager::_check_device(). Which gets called when adding a device watcher (BlueZManager::add_device_watcher()). As it turns out this method is called in BleakClientBlueZDBus::connect() line 184. Which is outside the try..except which does handle properly cleaning up the dbus connection in case of a failure.

Below you can find a Minimal Working Example. The increase of dbus connections can be seen with the help of the following command: dbus-send --system --print-reply --dest=org.freedesktop.DBus /org/freedesktop/DBus org.freedesktop.DBus.ListNames | wc -l

import os
import asyncio
from asyncio import sleep

os.environ['BLEAK_LOGGING'] = ''

from bleak import AdvertisementData, BleakClient, BleakScanner, BLEDevice


async def run() -> None:
    print("Start scanning")
    devices: dict[str, tuple[BLEDevice, AdvertisementData]] = await BleakScanner().discover(timeout=20, return_adv=True)

    print(f"Found {len(devices)} devices in last scan")

    for i in range(0, 120, 10):
        print(f'sleeping {i+10}/120 seconds')
        # sleep in order to make sure bluez 'forgets' the scanned devices
        await sleep(10)

    while True:
        # avoid spamming
        await sleep(1)
        for address in devices:
            await sleep(0.1)

            print(address)
            try:
                device = devices[address][0]
                async with BleakClient(device) as client:
                    # read battery
                    battery = int.from_bytes(await client.read_gatt_char('00002a19-0000-1000-8000-00805f9b34fb'), byteorder='little')
                    print(f"{client.address}: Battery level {battery}%")
            except Exception as e:
                print(e)
                continue


asyncio.run(run())

Logs

When running my test example script this, was the output of the commands. The first command ran just before starting the script, the second command ran after running the script for a while.

user:~$ dbus-send --system --print-reply --dest=org.freedesktop.DBus /org/freedesktop/DBus org.freedesktop.DBus.ListNames | wc -l
120
user:~$ dbus-send --system --print-reply --dest=org.freedesktop.DBus /org/freedesktop/DBus org.freedesktop.DBus.ListNames | wc -l
353