CODEWITHSUNDEEP
pythonbluetooth-lowenergypython-asynciopython-bleak
icc97
icc97

Reputation: 12793

BleakScanner timeout with asyncio.wait_for when function has returned

Description

I have a BleakScanner with a timeout. The timeout still occured after returning from the asyncio.wait_for function (20s after returning from the function). Any further scanning is then blocked with the following DBus error

What I Did

I have a gateway continually connecting to 4 of the same type of device in a round-robin fashion.

I ran the following code and get the log from the asyncio.TimeoutError even though asyncio.wait_for(_scan_with_timeout(filter, device_id), timeout) should have returned

async def scan(
    device_id, timeout=SCAN_TIMEOUT_S
) -> Optional[Tuple[BLEDevice, Set[str]]]:
    try:
        filter = get_device_filter(device_id)
        return await asyncio.wait_for(_scan_with_timeout(filter, device_id), timeout)
    except asyncio.TimeoutError:
        logger.info(
            f"Timeout reached. Device {device_id} not found after {timeout} seconds"
        )

    return None


async def _scan_with_timeout(filter, device_id):
    seen = set()
    async with BleakScanner() as scanner:
        async for device, advertisement in scanner.advertisement_data():
            found_device_id = get_device_id(device)
            if found_device_id and found_device_id.startswith(filter):
                logger.info(f"Found {device!r}")
                logger.debug(f"{advertisement!r}")
                logger.debug(f"platform_data: {advertisement.platform_data}")
                logger.debug(f"service_data: {advertisement.service_data}")
                seen.add(found_device_id)

            if found_device_id == device_id:
                logger.info(f"Connecting")
                return (device, seen)

Logs

These are the logs I have, I don't have any further in depth logs yet.

2024-08-13 15:25:10,187 | INFO | xtel | Found BLEDevice(D0:83:D4:00:A2:61, XAIRQ-00A261)
2024-08-13 15:25:10,385 | INFO | xtel | Found BLEDevice(D0:83:D4:00:A2:97, XAIRQ-00A297)
2024-08-13 15:25:10,426 | INFO | xtel | Found BLEDevice(D0:83:D4:00:A2:D1, XAIRQ-00A2D1)
2024-08-13 15:25:10,427 | INFO | xtel | Connecting
2024-08-13 15:25:30,122 | INFO | xtel | Timeout reached. Device D0:83:D4:00:A2:D1 not found after 30 seconds
2024-08-13 15:25:30,123 | INFO | xtel | Rendezvous failed
2024-08-13 15:25:30,124 | INFO | gateway | Device D0:83:D4:00:A2:D1 data collection: None.
2024-08-13 15:25:30,124 | INFO | gateway | Device D0:83:D4:00:A2:D1 status: DeviceStatus(t_slot_index=1, is_configured=True, is_defective=False, last_connect=1723562100.0084567, retry_count=1).
2024-08-13 15:25:30,125 | INFO | gateway | Time to sensor connect: 119.87453603744507
2024-08-13 15:27:30,098 | INFO | gateway | Time slots: ['D0:83:D4:00:A2:6A', 'D0:83:D4:00:A2:D1', 'D0:83:D4:00:A2:82', 'D0:83:D4:00:5E:9A']
2024-08-13 15:27:30,100 | INFO | xtel | Reconnecting to device to fetch data
2024-08-13 15:27:30,101 | INFO | xtel | Rendezvous - waiting for data...
2024-08-13 15:27:30,101 | INFO | xtel | Scanning for D0:83:D4:00:A2:82...
2024-08-13 15:27:30,107 | ERROR | xtel | Rendezvous connect failed because: BleakDBusError('org.bluez.Error.InProgress', 'Operation already in progress')
2024-08-13 15:27:30,108 | INFO | xtel | Rendezvous failed
2024-08-13 15:27:30,109 | INFO | gateway | Device D0:83:D4:00:A2:82 data collection: None.
2024-08-13 15:27:30,109 | INFO | gateway | Device D0:83:D4:00:A2:82 status: DeviceStatus(t_slot_index=2, is_configured=True, is_defective=False, last_connect=1723562250.0088952, retry_count=1).
2024-08-13 15:27:30,111 | INFO | gateway | Time to sensor connect: 149.88888812065125

These two lines are the ones that are the problem:

2024-08-13 15:25:10,427 | INFO | xtel | Connecting
2024-08-13 15:25:30,122 | INFO | xtel | Timeout reached. Device D0:83:D4:00:A2:D1 not found after 30 seconds

The "Connecting" log occurs just before the return of the function.

Upvotes: 0

Views: 67

Answers (1)

icc97
icc97

Reputation: 12793

Updated answer:

Comment from discussion #1629

As a final follow up to this, the async.timeout didn't solve the problem. What did, and I took inspiration from the Bleak source code is to switch the order of the context blocks. So that the async with asyncio.timeout is performed inside the async with BleakScanner context block.

bleak/bleak/init.py

Lines 444 to 451 in e01e264

 async with cls(**kwargs) as scanner: 
     try: 
         async with async_timeout(timeout): 
             async for bd, ad in scanner.advertisement_data(): 
                 if filterfunc(bd, ad): 
                     return bd 
     except asyncio.TimeoutError: 
         return None

Previous answer:

I asked this question also in the Bleak GitHub repo discussion #1629.

The answer was:

asyncio.wait_for() does not wait for canceled tasks to complete. You may have better luck with asyncio.timeout(). Otherwise you will need to protect the scanner with an asyncio.Lock() to prevent concurrent scanning.

It required upgrading to Python 3.11 and using asyncio.timeout. I also ensured the _scan_with_timeout returned None

async def scan(
    device_id, timeout=SCAN_TIMEOUT_S
) -> Optional[Tuple[BLEDevice, Set[str]]]:
    try:
        filter = get_device_filter(device_id)
        # Enforce a scanning timeout
        async with asyncio.timeout(timeout):
            return await _scan_with_timeout(filter, device_id)
    except asyncio.TimeoutError:
        logger.info(
            f"Timeout reached. Device {device_id} not found after {timeout} seconds"
        )

    return None


async def _scan_with_timeout(filter, device_id):
    seen = set()
    async with BleakScanner() as scanner:
        async for device, advertisement in scanner.advertisement_data():
            found_device_id = get_device_id(device)
            if found_device_id and found_device_id.startswith(filter):
                logger.info(f"Found {device!r}")
                logger.debug(f"{advertisement!r}")
                logger.debug(f"platform_data: {advertisement.platform_data}")
                logger.debug(f"service_data: {advertisement.service_data}")
                seen.add(found_device_id)

            if found_device_id == device_id:
                logger.info(f"Found desired {device!r}")
                return (device, seen)
    return None

Upvotes: 0

Related Questions