search

hbldh / bleak

A cross platform Bluetooth Low Energy Client for Python using asyncio
MIT License
1.64k stars 282 forks source link

Unreliable Reconnection to BLE Heart Rate Monitor #1402

Open nullstalgia opened 10 months ago

nullstalgia commented 10 months ago

Description

I am writing a script that connects to generic BLE Heart Rate Monitors (HRM) and sends the data to VRChat over OSC.

The script functions normally most of the time (minus all of the random exceptions I have to handle), but issues can occur when I walk out of the room while wearing the HRM, and later re-enter.

A good portion of the time, it will re-connect successfully, but there is a chance that the script will get stuck in a loop of attempting to connect and failing. And during this loop, it will give the same CancelledError regardless of if the HRM is even on anymore.

Restarting the script will often break this loop and allow the script to function again, but I really don't want to ask users to do that.

What I Did

Here is the full script in question, but below is my attempt at a Minimum Reproducible Example

import asyncio
import logging
from bleak import BleakScanner, BleakClient
from bleak.exc import BleakDeviceNotFoundError, BleakError
from bleak.backends.device import BLEDevice
from bleak.backends.characteristic import BleakGATTCharacteristic
from bleak.backends.scanner import AdvertisementData
from io import BytesIO
import time
from pprint import pformat, pprint
import struct
import sys
import traceback
from async_timeout import timeout

ble_address = "C8:45:A8:16:66:CC"

HEART_RATE_SERVICE_UUID = "0000180d-0000-1000-8000-00805f9b34fb"
HEART_RATE_MEASUREMENT_CHARACTERISTIC_UUID = "00002a37-0000-1000-8000-00805f9b34fb"

def read_hr_buffer(data):
    length = len(data)
    if length == 0:
        return None

    ms = BytesIO(data)
    flags = ms.read(1)[0]
    isshort = flags & 1
    contactSensor = (flags >> 1) & 3
    hasEnergyExpended = flags & 8
    hasRRInterval = flags & 16
    minLength = 3 if isshort else 2

    if len(data) < minLength:
        return None

    reading = {}
    reading['Flags'] = flags
    reading['Status'] = contactSensor
    reading['BeatsPerMinute'] = struct.unpack('<H', ms.read(2))[0] if isshort else ms.read(1)[0]

    if hasEnergyExpended:
        reading['EnergyExpended'] = struct.unpack('<H', ms.read(2))[0]

    if hasRRInterval:
        rrvalueCount = int((len(data) - ms.tell()) / 2)
        rrvalues = [struct.unpack('<H', ms.read(2))[0] for _ in range(rrvalueCount)]
        reading['RRIntervals'] = rrvalues

    return reading

class HeartRateMonitor:
    def __init__(self, device_address):
        self.device_address = device_address
        self.client = None
        self.connected = False
        self.last_battery_run = 0
        self.battery_characteristic = None
        self.receivedZero = 0
        self.receivedNonZero = 0

    async def connect(self):
        self.client = BleakClient(self.device_address, disconnected_callback=self.on_disconnect)
        print("Created client.")
        async with timeout(30) as cm:
            try:
                print("Connecting.")

                self.connected = await self.client.connect()
                if self.connected:
                    await self.client.start_notify(HEART_RATE_MEASUREMENT_CHARACTERISTIC_UUID, self.on_hr_data_received)
                    print("Connected!")
            except (asyncio.exceptions.CancelledError, TimeoutError):
                type, value, tb = sys.exc_info()
                print(f"Exception: {type} - {value}")
                print(f"{pformat(tb)}")
                print(f"{pformat(traceback.format_exc())}")
                print("Couldn't connect to device, try again?")
                pass
        if cm.expired:
            print("Connection should have timed out, but didn't throw an exception?")

    async def disconnect(self):
        #if self.connected:
        if self.client is not None:
            try:
                await self.client.stop_notify(HEART_RATE_MEASUREMENT_CHARACTERISTIC_UUID)
                await self.client.disconnect()
                print("Disconnected successfully?")
                self.connected = False
            except (KeyError, BleakError, AttributeError):
                # Not exactly sure why these get thrown, hopefully this helps
                # I think sometimes on disconnecting when it may already be DC'd, it just double freaks out and throws exceptions?

                # Adding this to see if it helps with not re-connecting after timing out/leaving BLE range.
                print("Exception handled while disconnecting.")
                self.connected = False
                pass

    def on_disconnect(self, client: BleakClient | None = None):
        self.connected = False
        print("Disconnected!")

    async def on_hr_data_received(self, characteristic: BleakGATTCharacteristic, data: bytearray) -> None:
        raw = read_hr_buffer(data)
        bpm = raw['BeatsPerMinute']
        if not self.connected or bpm == 0:
            self.battery_characteristic = None
        if bpm == 0:
            self.receivedZero += 1
            self.receivedNonZero = 0
            print("Received zero BPM...")

            print(f"Data: {data.hex()}")
        elif bpm > 0 and self.connected == False:
            self.receivedNonZero += 1
            self.receivedZero = 0

        if self.client is not None:
            if self.receivedZero > 10:
                self.connected = False
                await self.disconnect()
            elif self.receivedNonZero > 5:
                self.connected = True
                self.receivedNonZero = 0

        print(f"Received {bpm} BPM.")
        print(f"Connected: {self.connected}")

        await self.get_battery_level()

    async def get_battery_level(self):
       if self.connected and self.battery_characteristic is not None:
            if time.time() - self.last_battery_run > (5*60):
                if self.client is not None:
                    value = await self.client.read_gatt_char(self.battery_characteristic)
                    self.hrdata.update_battery(int.from_bytes(value, byteorder='little'))
                    self.last_battery_run = time.time()

async def main():
    monitor = HeartRateMonitor(ble_address)
    await monitor.connect()
    while True:
        await asyncio.sleep(1)
        if not monitor.connected:
            print("Not connected, reconnecting...")
            try:
                await monitor.connect()
            except TimeoutError:
                print("Connection timed out. Retrying in 3s...")
                await asyncio.sleep(3)
            except BleakDeviceNotFoundError:
                print("Device not found. Retrying in 3s...")
                await asyncio.sleep(3)
            except (BleakError, OSError):
                print("BLE Error. Retrying in 15s...")
                type, value, tb = sys.exc_info()
                print(f"Exception: {type} - {value}")
                await asyncio.sleep(15)
            except (asyncio.exceptions.CancelledError):
                print("System error? Probably not good. Retrying in 3s...")
                type, value, tb = sys.exc_info()
                print(f"Exception: {type} - {value}")
                await asyncio.sleep(3)

if __name__ == "__main__":
    asyncio.run(main())

Logs

Here is a sample of some of the errors I get saved into my log file

2023-08-27 01:58:50,828 - DEBUG - Exception: <class 'asyncio.exceptions.CancelledError'> - 
2023-08-27 01:58:50,828 - DEBUG - <traceback object at 0x0000013B91A56640>
2023-08-27 01:58:50,846 - DEBUG - ('Traceback (most recent call last):\n'
 '  File "PyHRPresence.py", line 344, in connect\n'
 '  File "bleak\\__init__.py", line 563, in connect\n'
 '  File "bleak\\backends\\winrt\\client.py", line 443, in connect\n'
 '  File "asyncio\\locks.py", line 213, in wait\n'
 'asyncio.exceptions.CancelledError\n')
2023-08-27 23:14:10,962 - DEBUG - Exception: <class 'TimeoutError'> - 
2023-08-27 23:14:10,963 - DEBUG - <traceback object at 0x000001C7B779B380>
2023-08-27 23:14:10,964 - DEBUG - ('Traceback (most recent call last):\n'
 '  File "bleak\\backends\\winrt\\client.py", line 435, in connect\n'
 '  File "bleak\\backends\\winrt\\client.py", line 687, in get_services\n'
 '  File "bleak\\backends\\winrt\\client.py", line 1072, in __await__\n'
 '  File "bleak\\backends\\winrt\\client.py", line 1007, in result\n'
 'asyncio.exceptions.CancelledError\n'
 '\n'
 'During handling of the above exception, another exception occurred:\n'
 '\n'
 'Traceback (most recent call last):\n'
 '  File "PyHRPresence.py", line 344, in connect\n'
 '  File "bleak\\__init__.py", line 563, in connect\n'
 '  File "bleak\\backends\\winrt\\client.py", line 391, in connect\n'
 '  File "asyncio\\timeouts.py", line 98, in __aexit__\n'
 'TimeoutError\n')

polar-wireshark-logs.zip

dlech commented 10 months ago

This sounds suspiciously like https://github.com/hbldh/bleak/issues/1359#issuecomment-1694902870. Does adding the delays suggested in the linked comment fix the issue for you?

nullstalgia commented 10 months ago

Apologies for delay, wanted to run it through for a few days to see how it affected it.

I think it's able to reconnect a bit more reliably, I was able to exit the vicinity a few times and not notice any hiccups.

But a few times, either when re-entering the space or sometimes, after I had returned, the issue would rear it's head again.

2023-09-02 15:41:09,988 - DEBUG - Exception: <class 'asyncio.exceptions.CancelledError'> - 
2023-09-02 15:41:09,988 - DEBUG - <traceback object at 0x000001D221E5C780>
2023-09-02 15:41:09,989 - DEBUG - ('Traceback (most recent call last):\n'
 '  File "PyHRPresence.py", line 344, in connect\n'
 '  File "bleak\\__init__.py", line 563, in connect\n'
 '  File "bleak\\backends\\winrt\\client.py", line 443, in connect\n'
 '  File "asyncio\\locks.py", line 213, in wait\n'
 'asyncio.exceptions.CancelledError\n')
2023-08-30 00:03:18,546 - DEBUG - ('Traceback (most recent call last):\n'
 '  File "PyHRPresence.py", line 344, in connect\n'
 '  File "bleak\\__init__.py", line 563, in connect\n'
 '  File "bleak\\backends\\winrt\\client.py", line 237, in connect\n'
 '  File "bleak\\__init__.py", line 346, in find_device_by_address\n'
 '  File "bleak\\__init__.py", line 402, in find_device_by_filter\n'
 '  File "bleak\\__init__.py", line 239, in advertisement_data\n'
 '  File "asyncio\\queues.py", line 158, in get\n'
 'asyncio.exceptions.CancelledError\n')

But I have not tested with v.0.21.0 yet. That's next on my to-do.

nullstalgia commented 10 months ago

@dlech So 0.21.0 seems more reliable? Hard to tell since its such a transient issue.

Symptoms vary, but today, BPM returned 0 for a bit, eventually raises a BleakError, then starts raising CancelledErrors.

Unsure how connected all of these are, but the main symptom of not being able to recover and reconnect until app restart stays a consistent theme.

Maybe some way to flush the setup bleak does could help?

A sampling some of the log errors:

2023-09-10 00:55:59,036 - DEBUG - Exception: <class 'TimeoutError'> - 
2023-09-10 00:55:59,037 - DEBUG - <traceback object at 0x000002086098BF40>
2023-09-10 00:55:59,038 - DEBUG - ('Traceback (most recent call last):\n'
 '  File "bleak\\backends\\winrt\\client.py", line 480, in connect\n'
 '  File "bleak\\backends\\winrt\\client.py", line 756, in get_services\n'
 '  File "bleak\\backends\\winrt\\client.py", line 1122, in __await__\n'
 '  File "bleak\\backends\\winrt\\client.py", line 1065, in result\n'
 'asyncio.exceptions.CancelledError\n'
 '\n'
 'During handling of the above exception, another exception occurred:\n'
 '\n'
 'Traceback (most recent call last):\n'
 '  File "PyHRPresence.py", line 344, in connect\n'
 '  File "bleak\\__init__.py", line 605, in connect\n'
 '  File "bleak\\backends\\winrt\\client.py", line 436, in connect\n'
 '  File "asyncio\\timeouts.py", line 98, in __aexit__\n'
 'TimeoutError\n')

2023-09-10 03:21:34,547 - DEBUG - Exception: <class 'asyncio.exceptions.CancelledError'> - 
2023-09-10 03:21:34,548 - DEBUG - <traceback object at 0x0000020860487540>
2023-09-10 03:21:34,548 - DEBUG - ('Traceback (most recent call last):\n'
 '  File "PyHRPresence.py", line 344, in connect\n'
 '  File "bleak\\__init__.py", line 605, in connect\n'
 '  File "bleak\\backends\\winrt\\client.py", line 282, in connect\n'
 '  File "bleak\\__init__.py", line 385, in find_device_by_address\n'
 '  File "bleak\\__init__.py", line 444, in find_device_by_filter\n'
 '  File "bleak\\__init__.py", line 244, in advertisement_data\n'
 '  File "asyncio\\queues.py", line 158, in get\n'
 'asyncio.exceptions.CancelledError\n')

2023-09-12 23:29:15,554 - DEBUG - Exception: <class 'asyncio.exceptions.CancelledError'> - 
2023-09-12 23:29:15,554 - DEBUG - <traceback object at 0x0000019C3707A1C0>
2023-09-12 23:29:15,555 - DEBUG - ('Traceback (most recent call last):\n'
 '  File "PyHRPresence.py", line 344, in connect\n'
 '  File "bleak\\__init__.py", line 605, in connect\n'
 '  File "bleak\\backends\\winrt\\client.py", line 488, in connect\n'
 '  File "asyncio\\locks.py", line 213, in wait\n'
 'asyncio.exceptions.CancelledError\n')
dlech commented 10 months ago

The asyncio.CancelledErrors are caused by the async with timeout(). Since the try/except is inside of the async with block, it is catching the CancelledError which would usually be masked by the asyncio.TimeoutError. I don't think there should be any try/except there.

But that still won't fix the Windows Bluetooth stack. We would need more detailed logs to see if there is anything we are leaving hanging (e.g. some closable object that we are not closing) that would be preventing things from working unless we restart the app.

nullstalgia commented 9 months ago

@dlech Aight, had it happen with debug logging on:

2023-09-16 00:20:39,760 - DEBUG - <traceback object at 0x000001B1F1858540>
2023-09-16 00:20:39,761 - DEBUG - ('Traceback (most recent call last):\n'
 '  File "PyHRPresence.py", line 344, in connect\n'
 '  File "bleak\\__init__.py", line 605, in connect\n'
 '  File "bleak\\backends\\winrt\\client.py", line 488, in connect\n'
 '  File "asyncio\\locks.py", line 213, in wait\n'
 'asyncio.exceptions.CancelledError\n')
2023-09-16 00:20:39,761 - ERROR - Couldn't connect to device, try again?
2023-09-16 00:20:39,762 - INFO - Attempting to reconnect...
2023-09-16 00:20:40,767 - INFO - Attempting to connect...
2023-09-16 00:20:40,768 - DEBUG - Created client.
2023-09-16 00:20:40,768 - DEBUG - Connecting.
2023-09-16 00:20:40,810 - DEBUG - Received 7A:AB:03:3A:4D:C8: .
2023-09-16 00:20:40,812 - DEBUG - Received 7A:AB:03:3A:4D:C8: .
2023-09-16 00:20:40,953 - DEBUG - Received 8C:79:F5:7F:8E:14: .
2023-09-16 00:20:40,955 - DEBUG - Received 8C:79:F5:7F:8E:14: [TV] Living Room TV (Q900).
2023-09-16 00:20:41,162 - DEBUG - Received EA:67:72:A1:49:84: LHB-CAAEDB12.
2023-09-16 00:20:41,163 - DEBUG - Received EA:67:72:A1:49:84: .
2023-09-16 00:20:41,165 - DEBUG - Received E2:C3:F9:D3:C3:3A: LHB-B95A8525.
2023-09-16 00:20:41,294 - DEBUG - Received E2:C3:F9:D3:C3:3A: LHB-B95A8525.
2023-09-16 00:20:41,295 - DEBUG - Received E2:C3:F9:D3:C3:3A: .
2023-09-16 00:20:41,420 - DEBUG - Received E2:C3:F9:D3:C3:3A: LHB-B95A8525.
2023-09-16 00:20:41,422 - DEBUG - Received E2:C3:F9:D3:C3:3A: .
2023-09-16 00:20:41,521 - DEBUG - Received C8:45:A8:16:66:CC: Polar H10 C1C93C2D.
2023-09-16 00:20:41,522 - DEBUG - 5 devices found. Watcher status: <BluetoothLEAdvertisementWatcherStatus.STOPPED: 3>.
2023-09-16 00:20:41,523 - DEBUG - Connecting to BLE device @ C8:45:A8:16:66:CC
2023-09-16 00:20:41,621 - DEBUG - getting services (service_cache_mode=None, cache_mode=None)...
2023-09-16 00:20:41,874 - DEBUG - skipping service 0000180d-0000-1000-8000-00805f9b34fb due to access denied
2023-09-16 00:20:41,881 - DEBUG - skipping service 0000181c-0000-1000-8000-00805f9b34fb due to access denied
2023-09-16 00:20:41,946 - DEBUG - skipping service 6217ff4b-fb31-1140-ad5a-a45545d7ecf3 due to access denied
2023-09-16 00:20:41,955 - DEBUG - skipping service fb005c80-02e7-f387-1cad-8acd2d8df0c8 due to access denied
2023-09-16 00:20:41,961 - DEBUG - skipping service 0000feee-0000-1000-8000-00805f9b34fb due to access denied
2023-09-16 00:21:10,766 - DEBUG - closing requester
2023-09-16 00:21:10,767 - DEBUG - closing session
2023-09-16 00:21:10,769 - DEBUG - Exception: <class 'asyncio.exceptions.CancelledError'> - 
2023-09-16 00:21:10,769 - DEBUG - <traceback object at 0x000001B1F2BC6600>
2023-09-16 00:21:10,770 - DEBUG - ('Traceback (most recent call last):\n'
 '  File "PyHRPresence.py", line 344, in connect\n'
 '  File "bleak\\__init__.py", line 605, in connect\n'
 '  File "bleak\\backends\\winrt\\client.py", line 488, in connect\n'
 '  File "asyncio\\locks.py", line 213, in wait\n'
 'asyncio.exceptions.CancelledError\n')
2023-09-16 00:21:10,770 - ERROR - Couldn't connect to device, try again?
2023-09-16 00:21:10,770 - INFO - Attempting to reconnect...
2023-09-16 00:21:11,787 - INFO - Attempting to connect...
2023-09-16 00:21:11,790 - DEBUG - Created client.
2023-09-16 00:21:11,790 - DEBUG - Connecting.
2023-09-16 00:21:11,837 - DEBUG - Received C8:45:A8:16:66:CC: Polar H10 C1C93C2D.
2023-09-16 00:21:11,839 - DEBUG - 1 devices found. Watcher status: <BluetoothLEAdvertisementWatcherStatus.STOPPED: 3>.
2023-09-16 00:21:11,839 - DEBUG - Connecting to BLE device @ C8:45:A8:16:66:CC
2023-09-16 00:21:11,969 - DEBUG - getting services (service_cache_mode=None, cache_mode=None)...
2023-09-16 00:21:12,279 - DEBUG - skipping service 0000180d-0000-1000-8000-00805f9b34fb due to access denied
2023-09-16 00:21:12,288 - DEBUG - skipping service 0000181c-0000-1000-8000-00805f9b34fb due to access denied
2023-09-16 00:21:12,357 - DEBUG - skipping service 6217ff4b-fb31-1140-ad5a-a45545d7ecf3 due to access denied
2023-09-16 00:21:12,364 - DEBUG - skipping service fb005c80-02e7-f387-1cad-8acd2d8df0c8 due to access denied
2023-09-16 00:21:12,371 - DEBUG - skipping service 0000feee-0000-1000-8000-00805f9b34fb due to access denied
2023-09-16 00:21:41,792 - DEBUG - closing requester
2023-09-16 00:21:41,793 - DEBUG - closing session
2023-09-16 00:21:41,794 - DEBUG - Exception: <class 'asyncio.exceptions.CancelledError'> - 
2023-09-16 00:21:41,794 - DEBUG - <traceback object at 0x000001B1F2BB3DC0>
2023-09-16 00:21:41,795 - DEBUG - ('Traceback (most recent call last):\n'
 '  File "PyHRPresence.py", line 344, in connect\n'
 '  File "bleak\\__init__.py", line 605, in connect\n'
 '  File "bleak\\backends\\winrt\\client.py", line 488, in connect\n'
 '  File "asyncio\\locks.py", line 213, in wait\n'
 'asyncio.exceptions.CancelledError\n')
2023-09-16 00:21:41,795 - ERROR - Couldn't connect to device, try again?
2023-09-16 00:21:41,795 - INFO - Attempting to reconnect...
2023-09-16 00:21:42,800 - INFO - Attempting to connect...
2023-09-16 00:21:42,802 - DEBUG - Created client.
2023-09-16 00:21:42,803 - DEBUG - Connecting.
2023-09-16 00:21:42,854 - DEBUG - Received EA:67:72:A1:49:84: LHB-CAAEDB12.
2023-09-16 00:21:42,855 - DEBUG - Received EA:67:72:A1:49:84: .
2023-09-16 00:21:42,984 - DEBUG - Received EA:67:72:A1:49:84: LHB-CAAEDB12.
2023-09-16 00:21:42,986 - DEBUG - Received EA:67:72:A1:49:84: .
2023-09-16 00:21:42,988 - DEBUG - Received E2:C3:F9:D3:C3:3A: LHB-B95A8525.
2023-09-16 00:21:42,989 - DEBUG - Received E2:C3:F9:D3:C3:3A: .
2023-09-16 00:21:43,207 - DEBUG - Received E2:C3:F9:D3:C3:3A: LHB-B95A8525.
2023-09-16 00:21:43,209 - DEBUG - Received E2:C3:F9:D3:C3:3A: .
2023-09-16 00:21:43,211 - DEBUG - Received EA:67:72:A1:49:84: LHB-CAAEDB12.
2023-09-16 00:21:43,212 - DEBUG - Received EA:67:72:A1:49:84: .
2023-09-16 00:21:43,461 - DEBUG - Received E2:C3:F9:D3:C3:3A: LHB-B95A8525.
2023-09-16 00:21:43,462 - DEBUG - Received E2:C3:F9:D3:C3:3A: .
2023-09-16 00:21:43,552 - DEBUG - Received E2:C3:F9:D3:C3:3A: LHB-B95A8525.
2023-09-16 00:21:43,554 - DEBUG - Received E2:C3:F9:D3:C3:3A: .
2023-09-16 00:21:43,555 - DEBUG - Received 7A:AB:03:3A:4D:C8: .
2023-09-16 00:21:43,557 - DEBUG - Received 7A:AB:03:3A:4D:C8: .
2023-09-16 00:21:43,691 - DEBUG - Received EA:67:72:A1:49:84: LHB-CAAEDB12.
2023-09-16 00:21:43,692 - DEBUG - Received EA:67:72:A1:49:84: .
2023-09-16 00:21:43,695 - DEBUG - Received E2:C3:F9:D3:C3:3A: LHB-B95A8525.
2023-09-16 00:21:43,697 - DEBUG - Received E2:C3:F9:D3:C3:3A: .
2023-09-16 00:21:44,037 - DEBUG - Received EA:67:72:A1:49:84: LHB-CAAEDB12.
2023-09-16 00:21:44,038 - DEBUG - Received EA:67:72:A1:49:84: .
2023-09-16 00:21:44,267 - DEBUG - Received EA:67:72:A1:49:84: LHB-CAAEDB12.
2023-09-16 00:21:44,268 - DEBUG - Received EA:67:72:A1:49:84: .
2023-09-16 00:21:44,271 - DEBUG - Received E2:C3:F9:D3:C3:3A: LHB-B95A8525.
2023-09-16 00:21:44,272 - DEBUG - Received E2:C3:F9:D3:C3:3A: .
2023-09-16 00:21:44,379 - DEBUG - Received DC:AB:5D:C3:19:35: .
2023-09-16 00:21:44,513 - DEBUG - Received 8C:79:F5:7F:8E:14: .
2023-09-16 00:21:44,514 - DEBUG - Received 8C:79:F5:7F:8E:14: [TV] Living Room TV (Q900).
2023-09-16 00:21:44,623 - DEBUG - Received C8:45:A8:16:66:CC: Polar H10 C1C93C2D.
2023-09-16 00:21:44,625 - DEBUG - 6 devices found. Watcher status: <BluetoothLEAdvertisementWatcherStatus.STOPPED: 3>.
2023-09-16 00:21:44,625 - DEBUG - Connecting to BLE device @ C8:45:A8:16:66:CC
2023-09-16 00:21:44,735 - DEBUG - getting services (service_cache_mode=None, cache_mode=None)...
2023-09-16 00:21:45,026 - DEBUG - skipping service 0000180d-0000-1000-8000-00805f9b34fb due to access denied
2023-09-16 00:21:45,033 - DEBUG - skipping service 0000181c-0000-1000-8000-00805f9b34fb due to access denied
2023-09-16 00:21:45,088 - DEBUG - skipping service 6217ff4b-fb31-1140-ad5a-a45545d7ecf3 due to access denied
2023-09-16 00:21:45,094 - DEBUG - skipping service fb005c80-02e7-f387-1cad-8acd2d8df0c8 due to access denied
2023-09-16 00:21:45,102 - DEBUG - skipping service 0000feee-0000-1000-8000-00805f9b34fb due to access denied
2023-09-16 04:35:47,515 - DEBUG - Exception: <class 'bleak.exc.BleakError'> - Could not get GATT services: Unreachable
2023-09-16 04:36:02,525 - INFO - Attempting to reconnect...
2023-09-16 04:36:03,539 - INFO - Attempting to connect...
2023-09-16 04:36:03,540 - DEBUG - Created client.
2023-09-16 04:36:03,540 - DEBUG - Connecting.
2023-09-16 04:36:03,707 - DEBUG - Received E2:C3:F9:D3:C3:3A: LHB-B95A8525.
2023-09-16 04:36:03,708 - DEBUG - Received E2:C3:F9:D3:C3:3A: .
2023-09-16 04:36:03,720 - DEBUG - Received 6F:21:06:40:74:3A: .
2023-09-16 04:36:03,723 - DEBUG - Received 6F:21:06:40:74:3A: .
2023-09-16 04:36:03,725 - DEBUG - Received EA:67:72:A1:49:84: LHB-CAAEDB12.
2023-09-16 04:36:03,945 - DEBUG - Received E2:C3:F9:D3:C3:3A: LHB-B95A8525.
2023-09-16 04:36:03,952 - DEBUG - Received 7A:35:24:2F:00:9F: .
2023-09-16 04:36:03,954 - DEBUG - Received 7A:35:24:2F:00:9F: .
2023-09-16 04:36:04,073 - DEBUG - Received EA:67:72:A1:49:84: LHB-CAAEDB12.
2023-09-16 04:36:04,180 - DEBUG - Received 8C:79:F5:7F:8E:14: .
2023-09-16 04:36:04,209 - DEBUG - Received EA:67:72:A1:49:84: LHB-CAAEDB12.
2023-09-16 04:36:04,210 - DEBUG - Received EA:67:72:A1:49:84: .
2023-09-16 04:36:04,305 - DEBUG - Received EA:67:72:A1:49:84: LHB-CAAEDB12.
2023-09-16 04:36:04,534 - DEBUG - Received EA:67:72:A1:49:84: LHB-CAAEDB12.
2023-09-16 04:36:04,535 - DEBUG - Received EA:67:72:A1:49:84: .
2023-09-16 04:36:04,661 - DEBUG - Received 8C:79:F5:7F:8E:14: .
2023-09-16 04:36:04,671 - DEBUG - Received E2:C3:F9:D3:C3:3A: LHB-B95A8525.
2023-09-16 04:36:04,673 - DEBUG - Received E2:C3:F9:D3:C3:3A: .
2023-09-16 04:36:04,674 - DEBUG - Received EA:67:72:A1:49:84: LHB-CAAEDB12.
2023-09-16 04:36:04,676 - DEBUG - Received EA:67:72:A1:49:84: .
2023-09-16 04:36:04,678 - DEBUG - Received 5B:CD:5D:57:69:6B: .
2023-09-16 04:36:04,780 - DEBUG - Received 7A:35:24:2F:00:9F: .
2023-09-16 04:36:04,781 - DEBUG - Received 7A:35:24:2F:00:9F: .
2023-09-16 04:36:04,889 - DEBUG - Received EA:67:72:A1:49:84: LHB-CAAEDB12.
2023-09-16 04:36:04,891 - DEBUG - Received EA:67:72:A1:49:84: .
2023-09-16 04:36:04,893 - DEBUG - Received E2:C3:F9:D3:C3:3A: LHB-B95A8525.
2023-09-16 04:36:04,894 - DEBUG - Received E2:C3:F9:D3:C3:3A: .
2023-09-16 04:36:05,018 - DEBUG - Received EA:67:72:A1:49:84: LHB-CAAEDB12.
2023-09-16 04:36:05,019 - DEBUG - Received EA:67:72:A1:49:84: .
2023-09-16 04:36:05,156 - DEBUG - Received E2:C3:F9:D3:C3:3A: LHB-B95A8525.
2023-09-16 04:36:05,243 - DEBUG - Received C8:45:A8:16:66:CC: .
2023-09-16 04:36:05,244 - DEBUG - 7 devices found. Watcher status: <BluetoothLEAdvertisementWatcherStatus.STOPPED: 3>.
2023-09-16 04:36:05,245 - DEBUG - Connecting to BLE device @ C8:45:A8:16:66:CC
2023-09-16 04:36:05,265 - DEBUG - getting services (service_cache_mode=None, cache_mode=None)...
2023-09-16 04:36:05,278 - DEBUG - closing requester
2023-09-16 04:36:05,280 - DEBUG - closing session
2023-09-16 04:36:05,281 - ERROR - BLE Error. Retrying in 15s...
2023-09-16 04:36:05,282 - DEBUG - Exception: <class 'bleak.exc.BleakError'> - Could not get GATT services: Unreachable
2023-09-16 04:36:20,298 - INFO - Attempting to reconnect...
2023-09-16 04:36:21,309 - INFO - Attempting to connect...
2023-09-16 04:36:21,310 - DEBUG - Created client.
2023-09-16 04:36:21,310 - DEBUG - Connecting.
2023-09-16 04:36:21,371 - DEBUG - Received EA:67:72:A1:49:84: LHB-CAAEDB12.
2023-09-16 04:36:21,372 - DEBUG - Received EA:67:72:A1:49:84: .
2023-09-16 04:36:21,496 - DEBUG - Received 8C:79:F5:7F:8E:14: .
2023-09-16 04:36:21,500 - DEBUG - Received EA:67:72:A1:49:84: LHB-CAAEDB12.
2023-09-16 04:36:21,501 - DEBUG - Received EA:67:72:A1:49:84: .
2023-09-16 04:36:21,507 - DEBUG - Received E2:C3:F9:D3:C3:3A: LHB-B95A8525.
2023-09-16 04:36:21,755 - DEBUG - Received E2:C3:F9:D3:C3:3A: LHB-B95A8525.
2023-09-16 04:36:21,756 - DEBUG - Received E2:C3:F9:D3:C3:3A: .
2023-09-16 04:36:21,952 - DEBUG - Received EA:67:72:A1:49:84: LHB-CAAEDB12.
2023-09-16 04:36:21,954 - DEBUG - Received EA:67:72:A1:49:84: .
2023-09-16 04:36:21,957 - DEBUG - Received E2:C3:F9:D3:C3:3A: LHB-B95A8525.
2023-09-16 04:36:21,959 - DEBUG - Received E2:C3:F9:D3:C3:3A: .
2023-09-16 04:36:22,077 - DEBUG - Received EA:67:72:A1:49:84: LHB-CAAEDB12.
2023-09-16 04:36:22,078 - DEBUG - Received EA:67:72:A1:49:84: .
2023-09-16 04:36:22,214 - DEBUG - Received EA:67:72:A1:49:84: LHB-CAAEDB12.
2023-09-16 04:36:22,215 - DEBUG - Received EA:67:72:A1:49:84: .
2023-09-16 04:36:22,424 - DEBUG - Received C8:45:A8:16:66:CC: .
2023-09-16 04:36:22,425 - DEBUG - 4 devices found. Watcher status: <BluetoothLEAdvertisementWatcherStatus.STOPPED: 3>.
2023-09-16 04:36:22,426 - DEBUG - Received C8:45:A8:16:66:CC: Polar H10 C1C93C2D.
2023-09-16 04:36:22,426 - DEBUG - Connecting to BLE device @ C8:45:A8:16:66:CC
2023-09-16 04:36:22,538 - DEBUG - getting services (service_cache_mode=None, cache_mode=None)...
2023-09-16 04:36:22,560 - DEBUG - closing requester
2023-09-16 04:36:22,561 - DEBUG - closing session
2023-09-16 04:36:22,562 - ERROR - BLE Error. Retrying in 15s...
2023-09-16 04:36:22,564 - DEBUG - Exception: <class 'bleak.exc.BleakError'> - Could not get GATT services: Unreachable
2023-09-16 04:36:37,569 - INFO - Attempting to reconnect...
2023-09-16 04:36:38,584 - INFO - Attempting to connect...
2023-09-16 04:36:38,585 - DEBUG - Created client.
2023-09-16 04:36:38,585 - DEBUG - Connecting.
2023-09-16 04:36:38,650 - DEBUG - Received EA:67:72:A1:49:84: LHB-CAAEDB12.
2023-09-16 04:36:38,651 - DEBUG - Received EA:67:72:A1:49:84: .
2023-09-16 04:36:38,761 - DEBUG - Received E2:C3:F9:D3:C3:3A: LHB-B95A8525.
2023-09-16 04:36:38,763 - DEBUG - Received E2:C3:F9:D3:C3:3A: .
2023-09-16 04:36:38,770 - DEBUG - Received C8:45:A8:16:66:CC: .
2023-09-16 04:36:38,772 - DEBUG - 3 devices found. Watcher status: <BluetoothLEAdvertisementWatcherStatus.STOPPED: 3>.
2023-09-16 04:36:38,772 - DEBUG - Received C8:45:A8:16:66:CC: Polar H10 C1C93C2D.
2023-09-16 04:36:38,774 - DEBUG - Connecting to BLE device @ C8:45:A8:16:66:CC
2023-09-16 04:36:38,797 - DEBUG - getting services (service_cache_mode=None, cache_mode=None)...
2023-09-16 04:36:38,810 - DEBUG - closing requester
2023-09-16 04:36:38,810 - DEBUG - closing session
2023-09-16 04:36:38,811 - ERROR - BLE Error. Retrying in 15s...
2023-09-16 04:36:38,812 - DEBUG - Exception: <class 'bleak.exc.BleakError'> - Could not get GATT services: Unreachable
2023-09-16 04:36:53,829 - INFO - Attempting to reconnect...
2023-09-16 04:36:54,841 - INFO - Attempting to connect...
2023-09-16 04:36:54,843 - DEBUG - Created client.
2023-09-16 04:36:54,843 - DEBUG - Connecting.
2023-09-16 04:36:55,021 - DEBUG - Received 8C:79:F5:7F:8E:14: .
2023-09-16 04:36:55,026 - DEBUG - Received 5B:CD:5D:57:69:6B: .
2023-09-16 04:36:55,028 - DEBUG - Received 5B:CD:5D:57:69:6B: .

And no extra entries for 30 mins until I noticed it was dead in-game.

nullstalgia commented 9 months ago

@dlech Is there more types of logging you would need? Not sure how to proceed from here.