0
  • bleak version: 0.22.2
  • Python version: 3.8.18
  • Operating System: Linux
  • BlueZ version (bluetoothctl -v) in case of Linux: 5.64

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.

Improve this question
1
  • 1
    "The Connecting log occurs just before the return of the function." Not exactly. The function will not return until the context manager is closed. The line async with BleakScanner() as scanner creates an implicit call to scanner.__aexit__ that must execute before the actual return can happen. My guess is that some shutdown code in there is taking too long and you get a timeout. Commented Aug 15, 2024 at 7:43

1 Answer 1

Reset to default
0

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
Improve this answer
Sign up to request clarification or add additional context in comments.

Comments

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Start asking to get answers

Find the answer to your question by asking.

Ask question

Explore related questions

See similar questions with these tags.