diff --git a/src/yalexs_ble/lock.py b/src/yalexs_ble/lock.py index db142ac..e933426 100644 --- a/src/yalexs_ble/lock.py +++ b/src/yalexs_ble/lock.py @@ -391,8 +391,17 @@ async def disconnect(self) -> None: try: await self._shutdown_connection() + except BleakError: + _LOGGER.debug( + "%s: Failed to shutdown connection to lock", self.name, exc_info=True + ) finally: - await self.client.disconnect() + try: + await self.client.disconnect() + except BleakError: + _LOGGER.debug( + "%s: Failed to disconnect from lock", self.name, exc_info=True + ) async def _shutdown_connection(self) -> None: """Shutdown the connection.""" diff --git a/src/yalexs_ble/push.py b/src/yalexs_ble/push.py index 4186326..eee9778 100644 --- a/src/yalexs_ble/push.py +++ b/src/yalexs_ble/push.py @@ -51,8 +51,12 @@ DEFAULT_ATTEMPTS = 4 +# How long to wait to disconnect after an operation DISCONNECT_DELAY = 5.1 +# How long to wait to disconnect after an operation if there is a pending update +DISCONNECT_DELAY_PENDING_UPDATE = 12.5 + RESYNC_DELAY = 0.01 KEEP_ALIVE_TIME = 25.0 # Lock will disconnect after 30 seconds of inactivity @@ -81,7 +85,7 @@ POST_OPERATION_SYNC_TIME = 10.00 # How long to wait if we get an update storm from the lock -UPDATE_IN_PROGRESS_DEFER_SECONDS = 1.0 +UPDATE_IN_PROGRESS_DEFER_SECONDS = DISCONNECT_DELAY - 1 RETRY_BACKOFF_EXCEPTIONS = (BleakDBusError, DisconnectedError) @@ -155,7 +159,16 @@ async def _async_wrap_retry_bluetooth_connection_error( # authentications in a row we can reasonably assume that the key has # changed and we should re-authenticate. self._update_any_state([AuthState(successful=False)]) - raise + raise + _LOGGER.debug( + "%s: Auth error calling %s, retrying (%s/%s)...", + self.name, + func, + attempt, + max_attempts, + exc_info=True, + ) + await asyncio.sleep(0.25) except BleakNotFoundError: # The lock cannot be found so there is no # point in retrying. @@ -227,6 +240,7 @@ def __init__( advertisement_data: AdvertisementData | None = None, idle_disconnect_delay: float = DISCONNECT_DELAY, always_connected: bool = False, + idle_disconnect_delay_pending_update: float = DISCONNECT_DELAY_PENDING_UPDATE, ) -> None: """Init the lock watcher.""" if local_name is None and address is None: @@ -259,12 +273,17 @@ def __init__( self._seen_this_session: set[ type[LockStatus] | type[DoorStatus] | type[BatteryState] | type[AuthState] ] = set() - self._disconnect_or_keep_alive_timer: asyncio.TimerHandle | None = None + self._disconnect_timer: asyncio.TimerHandle | None = None + self._keep_alive_timer: asyncio.TimerHandle | None = None + self._idle_disconnect_delay_pending_update = ( + idle_disconnect_delay_pending_update + ) self._idle_disconnect_delay = idle_disconnect_delay self._next_disconnect_delay = idle_disconnect_delay self._first_update_future: asyncio.Future[None] | None = None self._background_tasks: set[asyncio.Task[None]] = set() self._last_lock_operation_complete_time = NEVER_TIME + self._last_operation_complete_time = NEVER_TIME self._always_connected = always_connected @property @@ -328,6 +347,11 @@ def ble_device(self) -> BLEDevice | None: """Return the current BLEDevice.""" return self._ble_device + @property + def is_connected(self) -> bool: + """Return if the lock is connected.""" + return bool(self._client and self._client.is_connected) + def set_name(self, name: str) -> None: """Set the name of the lock.""" self._name = name @@ -390,30 +414,55 @@ def _disconnected_callback(self) -> None: def _keep_alive(self) -> None: """Keep the lock connection alive.""" - self._schedule_future_update_with_debounce(0) - self._reset_disconnect_or_keep_alive_timer() + if not self._always_connected: + return + _LOGGER.debug("%s: Executing keep alive", self.name) + self._schedule_future_update(0) + self._schedule_next_keep_alive(KEEP_ALIVE_TIME) + + def _time_since_last_operation(self) -> float: + """Return the time since the last operation.""" + return time.monotonic() - self._last_operation_complete_time + + def _reschedule_next_keep_alive(self) -> None: + """Reschedule the next keep alive.""" + next_keep_alive_time = max( + 0, KEEP_ALIVE_TIME - self._time_since_last_operation() + ) + self._schedule_next_keep_alive(next_keep_alive_time) + + def _schedule_next_keep_alive(self, delay: float) -> None: + """Schedule the next keep alive.""" + self._cancel_keepalive_timer() + if not self._always_connected: + return + _LOGGER.debug( + "%s: Scheduling next keep alive in %s seconds", + self.name, + delay, + ) + self._keep_alive_timer = self.loop.call_later( + delay, + self._keep_alive, + ) - def _reset_disconnect_or_keep_alive_timer(self) -> None: + def _reset_disconnect_timer(self) -> None: """Reset disconnect timer.""" - self._cancel_disconnect_or_keep_alive_timer() - self._expected_disconnect = False if self._always_connected: - self._disconnect_or_keep_alive_timer = self.loop.call_later( - KEEP_ALIVE_TIME, self._keep_alive - ) return - + self._cancel_disconnect_timer() + self._expected_disconnect = False timeout = self._next_disconnect_delay _LOGGER.debug( "%s: Resetting disconnect timer to %s seconds", self.name, timeout ) - self._disconnect_or_keep_alive_timer = self.loop.call_later( + self._disconnect_timer = self.loop.call_later( timeout, self._disconnect_with_timer, timeout ) async def _execute_forced_disconnect(self, reason: str) -> None: """Execute forced disconnection.""" - self._cancel_disconnect_or_keep_alive_timer() + self._cancel_disconnect_timer() _LOGGER.debug("%s: Executing forced disconnect: %s", self.name, reason) if (update_task := self._update_task) and not update_task.done(): self._update_task = None @@ -425,28 +474,34 @@ async def _execute_forced_disconnect(self, reason: str) -> None: def _disconnect_with_timer(self, timeout: float) -> None: """Disconnect from device. - This should only ever be called from _reset_disconnect_or_keep_alive_timer + This should only ever be called from _reset_disconnect_timer """ if self._operation_lock.locked(): _LOGGER.debug("%s: Disconnect timer reset due to operation lock", self.name) - self._reset_disconnect_or_keep_alive_timer() + self._reset_disconnect_timer() return if self._cancel_deferred_update: _LOGGER.debug( "%s: Disconnect timer fired while we were waiting to update", self.name ) - self._reset_disconnect_or_keep_alive_timer() + self._reset_disconnect_timer() self._cancel_future_update() self._deferred_update() return - self._cancel_disconnect_or_keep_alive_timer() + self._cancel_disconnect_timer() self.background_task(self._execute_timed_disconnect(timeout)) - def _cancel_disconnect_or_keep_alive_timer(self) -> None: + def _cancel_disconnect_timer(self) -> None: """Cancel disconnect timer.""" - if self._disconnect_or_keep_alive_timer: - self._disconnect_or_keep_alive_timer.cancel() - self._disconnect_or_keep_alive_timer = None + if self._disconnect_timer: + self._disconnect_timer.cancel() + self._disconnect_timer = None + + def _cancel_keepalive_timer(self) -> None: + """Cancel keep alive timer.""" + if self._keep_alive_timer: + self._keep_alive_timer.cancel() + self._keep_alive_timer = None async def _execute_timed_disconnect(self, timeout: float) -> None: """Execute timed disconnection.""" @@ -466,15 +521,13 @@ async def _async_handle_disconnected(self, exc: Exception) -> None: self.name, ) return - self._cancel_disconnect_or_keep_alive_timer() + self._cancel_disconnect_timer() await self._execute_disconnect() async def _execute_disconnect(self) -> None: """Execute disconnection.""" async with self._connect_lock: - if ( - self._disconnect_or_keep_alive_timer - ): # If the timer was reset, don't disconnect + if self._disconnect_timer: # If the timer was reset, don't disconnect return client = self._client self._client = None @@ -486,18 +539,20 @@ async def _execute_disconnect(self) -> None: async def _ensure_connected(self) -> Lock: """Ensure connection to device is established.""" if self._connect_lock.locked(): - self._reset_disconnect_or_keep_alive_timer() + self._reset_disconnect_timer() _LOGGER.debug( "%s: Connection already in progress, waiting for it to complete", self.name, ) - if self._client and self._client.is_connected: - self._reset_disconnect_or_keep_alive_timer() + if self.is_connected: + assert self._client is not None # nosec + self._reset_disconnect_timer() return self._client async with self._connect_lock: # Check again while holding the lock - if self._client and self._client.is_connected: - self._reset_disconnect_or_keep_alive_timer() + if self.is_connected: + assert self._client is not None # type: ignore[unreachable] # nosec + self._reset_disconnect_timer() return self._client self._client = self._get_lock_instance() try: @@ -509,7 +564,7 @@ async def _ensure_connected(self) -> Lock: await self._client.disconnect() raise self._next_disconnect_delay = self._idle_disconnect_delay - self._reset_disconnect_or_keep_alive_timer() + self._reset_disconnect_timer() self._seen_this_session.clear() return self._client @@ -551,14 +606,17 @@ async def _execute_lock_operation( raise self._update_any_state([complete_state]) _LOGGER.debug("%s: Finished %s", self.name, complete_state) - self._last_lock_operation_complete_time = time.monotonic() - self._reset_disconnect_or_keep_alive_timer() + now = time.monotonic() + self._last_lock_operation_complete_time = now + self._last_operation_complete_time = now + self._reset_disconnect_timer() + self._reschedule_next_keep_alive() def _state_callback( self, states: Iterable[LockStatus | DoorStatus | BatteryState] ) -> None: """Handle state change.""" - self._reset_disconnect_or_keep_alive_timer() + self._reset_disconnect_timer() self._update_any_state(states) def _get_current_state(self) -> LockState: @@ -605,10 +663,9 @@ def _update_any_state( async def update(self) -> None: """Request that status be updated.""" + _LOGGER.debug("%s: Starting manual update", self.name) self._schedule_future_update_with_debounce( - 0 - if self._client and self._client.is_connected - else MANUAL_UPDATE_COALESCE_SECONDS + 0 if self.is_connected else MANUAL_UPDATE_COALESCE_SECONDS ) async def validate(self) -> None: @@ -662,6 +719,7 @@ async def _update(self) -> LockState: if LockStatus not in self._seen_this_session or ( not made_request and self._always_connected ): + made_request = True lock_status = await lock.lock_status() _AUTH_FAILURE_HISTORY.auth_success(self.address) state = replace(state, lock=lock_status, auth=AuthState(successful=True)) @@ -693,8 +751,11 @@ async def _update(self) -> LockState: # so that if another update request is pending # we do not disconnect until it completes. self._next_disconnect_delay = FIRST_CONNECTION_DISCONNECT_TIME - self._reset_disconnect_or_keep_alive_timer() + self._reset_disconnect_timer() + if made_request: + self._last_operation_complete_time = time.monotonic() + self._reschedule_next_keep_alive() return state def _callback_state(self, lock_state: LockState) -> None: @@ -792,8 +853,26 @@ def update_advertisement( next_update, scheduled_update, ) - if next_update: - self._schedule_future_update_with_debounce(next_update) + if not next_update: + return + if ( + self.is_connected + and self._next_disconnect_delay != FIRST_CONNECTION_DISCONNECT_TIME + and ( + self._time_since_last_operation() + + self._idle_disconnect_delay_pending_update + ) + < KEEP_ALIVE_TIME + ): + # Already connected, state will be pushed, but stay + # connected a bit longer to make sure we get it unless + # this is the first connection or deferring the update + # would keep the connection idle for too long and + # get us disconnected anyways. + self._next_disconnect_delay = self._idle_disconnect_delay_pending_update + self._reset_disconnect_timer() + return + self._schedule_future_update_with_debounce(next_update) async def start(self) -> Callable[[], None]: """Start watching for updates.""" @@ -846,10 +925,9 @@ def _cancel_future_update(self) -> None: def _schedule_future_update_with_debounce(self, seconds: float) -> None: """Schedule an update with a potential debounce.""" - now = self.loop.time() future_update_time = seconds if self._cancel_deferred_update: - time_till_update = self._cancel_deferred_update.when() - now + time_till_update = self._cancel_deferred_update.when() - self.loop.time() if time_till_update < HK_UPDATE_COALESCE_SECONDS: future_update_time = HK_UPDATE_COALESCE_SECONDS _LOGGER.debug( @@ -866,7 +944,9 @@ def _schedule_future_update_with_debounce(self, seconds: float) -> None: time_till_update, ) return - _LOGGER.debug("%s: Rescheduling update", self.name) + _LOGGER.debug( + "%s: Rescheduling update for %s", self.name, future_update_time + ) self._schedule_future_update(future_update_time) def _schedule_future_update(self, future_update_time: float) -> None: diff --git a/src/yalexs_ble/session.py b/src/yalexs_ble/session.py index aa83b23..76a84bc 100644 --- a/src/yalexs_ble/session.py +++ b/src/yalexs_ble/session.py @@ -268,6 +268,9 @@ async def execute(self, command: bytearray, command_name: str) -> bytes: if disconnect_task.done(): write_task.cancel() if write_task.done(): + with contextlib.suppress(asyncio.CancelledError, Exception): + disconnect_task.cancel() + await disconnect_task try: return await write_task except BleakError as err: