Weird device disconnection behavior

[vboginskey]

Hi,

I have a program that connects to several lithium batteries, polls them for data, and sends the data to InfluxDB. After running for a day or so, it just stops printing output or sending data. In the logs, I see that one device disconnects first, so my next step is to handle this with a disconnection callback.

My question is: shouldn't the program throw an exception or stop running? It just sits there waiting forever:

strace: Process 16562 attached
epoll_pwait(3,

Here is the relevant code:

async def main():
    async with asyncio.TaskGroup() as tg:
        for battery in batteries:
            tg.create_task(monitor_and_report(battery, influx))
            tg.create_task(report_successes(battery))
            
async def monitor_and_report(battery, influx):
    async with BleakClient(battery.device) as client:
        await client.start_notify(characteristic, callback)
        while True:
            for data in UT1300.COMMANDS.values():
                await client.write_gatt_char(characteristic, data, response=True)
                await asyncio.sleep(COMMAND_INTERVAL)
                
async def report_successes(battery):
    while True:
        await asyncio.sleep(REPORT_INTERVAL)
        battery.report_successes() # this method is just a single `logging.info` statement
        
asyncio.run(main(), debug=True)

The really strange thing (to me, at least) is that battery.report_successes() also stops printing output. If all the tasks were cancelled, then surely the program would exit, so that tells me one of the tasks is waiting indefinitely for something and hanging the event loop.

This is what I see in the logs:

Nov 02 00:11:03 bmvpi python[20978]: 2023-11-02 00:11:03,763 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChang
ed (/org/bluez/hci0/dev_77_77_19_0D_E2_B0): ['org.bluez.Device1', {'ServicesResolved': <dbus_fast.signature.Variant ('b', False)>, 'Connected': <dbus_fast.signature.Variant ('b', Fal
se)>}, []]
Nov 02 00:11:03 bmvpi python[20978]: DEBUG: received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_77_77_19_0D_E2_B0): ['org.bluez.Device1', {'
ServicesResolved': <dbus_fast.signature.Variant ('b', False)>, 'Connected': <dbus_fast.signature.Variant ('b', False)>}, []]
Nov 02 00:11:03 bmvpi python[20978]: 2023-11-02 00:11:03,764 bleak.backends.bluezdbus.client MainThread DEBUG: Device disconnected (/org/bluez/hci0/dev_77_77_19_0D_E2_B0)
Nov 02 00:11:03 bmvpi python[20978]: DEBUG: Device disconnected (/org/bluez/hci0/dev_77_77_19_0D_E2_B0)
Nov 02 00:11:03 bmvpi python[20978]: 2023-11-02 00:11:03,765 bleak.backends.bluezdbus.client MainThread DEBUG: _cleanup_all(/org/bluez/hci0/dev_77_77_19_0D_E2_B0)
Nov 02 00:11:03 bmvpi python[20978]: DEBUG: _cleanup_all(/org/bluez/hci0/dev_77_77_19_0D_E2_B0)
Nov 02 00:11:03 bmvpi python[20978]: 2023-11-02 00:11:03,768 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRe
moved (/): ['/org/bluez/hci0/dev_77_77_19_0D_E2_B0', ['org.bluez.Battery1']]
Nov 02 00:11:03 bmvpi python[20978]: DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci0/dev_77_77_19_0D_E2_B0', ['org.bluez.Bat
tery1']]
Nov 02 00:11:03 bmvpi python[20978]: 2023-11-02 00:11:03,771 bleak.backends.bluezdbus.client MainThread DEBUG: Disconnecting ({/org/bluez/hci0/dev_77_77_19_0D_E2_B0})
Nov 02 00:11:03 bmvpi python[20978]: DEBUG: Disconnecting ({/org/bluez/hci0/dev_77_77_19_0D_E2_B0})
Nov 02 00:11:03 bmvpi python[20978]: 2023-11-02 00:11:03,772 bleak.backends.bluezdbus.client MainThread DEBUG: already disconnected ({/org/bluez/hci0/dev_77_77_19_0D_E2_B0})
Nov 02 00:11:03 bmvpi python[20978]: DEBUG: already disconnected ({/org/bluez/hci0/dev_77_77_19_0D_E2_B0})
Nov 02 00:11:03 bmvpi python[20978]: 2023-11-02 00:11:03,773 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChang
ed (/org/bluez/hci0/dev_77_77_19_0D_E2_B0/service000b/char000c): ['org.bluez.GattCharacteristic1', {'Notifying': <dbus_fast.signature.Variant ('b', False)>}, []]
Nov 02 00:11:03 bmvpi python[20978]: DEBUG: received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_77_77_19_0D_E2_B0/service000b/char000c): ['o
rg.bluez.GattCharacteristic1', {'Notifying': <dbus_fast.signature.Variant ('b', False)>}, []]
Nov 02 00:11:03 bmvpi python[20978]: 2023-11-02 00:11:03,778 bleak.backends.bluezdbus.client MainThread DEBUG: Disconnecting ({/org/bluez/hci0/dev_77_77_19_0D_F3_3C})
Nov 02 00:11:03 bmvpi python[20978]: DEBUG: Disconnecting ({/org/bluez/hci0/dev_77_77_19_0D_F3_3C})
Nov 02 00:11:03 bmvpi python[20978]: 2023-11-02 00:11:03,785 bleak.backends.bluezdbus.client MainThread DEBUG: Disconnecting ({/org/bluez/hci0/dev_01_B6_EC_10_CB_8F})
Nov 02 00:11:03 bmvpi python[20978]: DEBUG: Disconnecting ({/org/bluez/hci0/dev_01_B6_EC_10_CB_8F})
Nov 02 00:11:03 bmvpi python[20978]: 2023-11-02 00:11:03,792 bleak.backends.bluezdbus.client MainThread DEBUG: Disconnecting ({/org/bluez/hci0/dev_01_B6_EC_0F_50_15})
Nov 02 00:11:03 bmvpi python[20978]: DEBUG: Disconnecting ({/org/bluez/hci0/dev_01_B6_EC_0F_50_15})
[snip]
Nov 02 00:11:36 bmvpi python[20978]: DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci0/dev_77_77_19_0D_F3_3C', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.Device1']]

I searched discussions and issues and reviewed #1216, https://github.com/hbldh/bleak/blob/develop/examples/disconnect_callback.py, and #933 among others, but wasn't able to answer this question.

Thanks for the help!

[dlech]

It is hard to say without seeing the full program and the full logs.